From 29e5ac13626bbad0f7513ada8ed41e534982c278 Mon Sep 17 00:00:00 2001 From: Thibault Saunier Date: Sun, 28 Aug 2016 20:37:05 -0300 Subject: [PATCH] validate: Enhance not-negotiated errors reporting Keeping negotation information around and trying to figure out precisely why the elements could not negotied the caps when we get a NOT_NEGOTIATED error on the bus giving the user details about it. --- validate/gst/validate/Makefile.am | 2 +- .../gst/validate/gst-validate-pad-monitor.c | 25 +- .../gst/validate/gst-validate-pad-monitor.h | 6 +- .../validate/gst-validate-pipeline-monitor.c | 256 ++++++++++++++++++ validate/gst/validate/gst-validate-report.c | 3 + validate/gst/validate/gst-validate-report.h | 3 +- 6 files changed, 291 insertions(+), 4 deletions(-) diff --git a/validate/gst/validate/Makefile.am b/validate/gst/validate/Makefile.am index df29f1173f..79419a6fd3 100644 --- a/validate/gst/validate/Makefile.am +++ b/validate/gst/validate/Makefile.am @@ -65,7 +65,7 @@ libgstvalidate_@GST_API_VERSION@includedir = $(includedir)/gstreamer-@GST_API_VE plugin_LTLIBRARIES = libgstvalidateplugin-@GST_API_VERSION@.la libgstvalidateplugin_@GST_API_VERSION@_la_SOURCES = $(source_c) libgstvalidateplugin_@GST_API_VERSION@_la_CFLAGS = $(GST_ALL_CFLAGS)\ - $(GIO_CFLAGS) $(GST_PBUTILS_CFLAGS) \ + $(JSON_GLIB_CFLAGS) $(GIO_CFLAGS) $(GST_PBUTILS_CFLAGS) \ -DGST_USE_UNSTABLE_API \ -D__GST_VALIDATE_PLUGIN libgstvalidateplugin_@GST_API_VERSION@_la_LDFLAGS = $(GST_LIB_LDFLAGS) $(GST_ALL_LDFLAGS) \ diff --git a/validate/gst/validate/gst-validate-pad-monitor.c b/validate/gst/validate/gst-validate-pad-monitor.c index 60df39917f..000b2b959a 100644 --- a/validate/gst/validate/gst-validate-pad-monitor.c +++ b/validate/gst/validate/gst-validate-pad-monitor.c @@ -2225,11 +2225,26 @@ gst_validate_pad_monitor_query_func (GstPad * pad, GstObject * parent, gboolean ret; gst_validate_pad_monitor_query_overrides (pad_monitor, query); - ret = pad_monitor->query_func (pad, parent, query); if (ret) { switch (GST_QUERY_TYPE (query)) { + case GST_QUERY_ACCEPT_CAPS: + { + gboolean result; + + gst_caps_replace (&pad_monitor->last_refused_caps, NULL); + gst_query_parse_accept_caps_result (query, &result); + if (!result) { + GstCaps *refused_caps; + + gst_query_parse_accept_caps (query, &refused_caps); + pad_monitor->last_refused_caps = gst_caps_copy (refused_caps); + + } + + break; + } case GST_QUERY_CAPS:{ GstCaps *res; GstCaps *filter; @@ -2240,6 +2255,14 @@ gst_validate_pad_monitor_query_func (GstPad * pad, GstObject * parent, gst_query_parse_caps (query, &filter); gst_query_parse_caps_result (query, &res); + + gst_caps_replace (&pad_monitor->last_query_res, NULL); + gst_caps_replace (&pad_monitor->last_query_filter, NULL); + pad_monitor->last_query_res = + res ? gst_caps_copy (res) : gst_caps_ref (GST_CAPS_NONE); + pad_monitor->last_query_filter = + filter ? gst_caps_copy (filter) : gst_caps_ref (GST_CAPS_NONE); + if (GST_PAD_DIRECTION (pad) == GST_PAD_SINK) { gst_validate_pad_monitor_check_caps_fields_proxied (pad_monitor, res, filter); diff --git a/validate/gst/validate/gst-validate-pad-monitor.h b/validate/gst/validate/gst-validate-pad-monitor.h index ef6e24398e..ecb6596c40 100644 --- a/validate/gst/validate/gst-validate-pad-monitor.h +++ b/validate/gst/validate/gst-validate-pad-monitor.h @@ -92,7 +92,7 @@ struct _GstValidatePadMonitor { /* Whether the next buffer should have a DISCONT flag on it, because * it's the first one, or follows a SEGMENT and/or a FLUSH */ gboolean pending_buffer_discont; - + GstClockTime pending_seek_accurate_time; GstEvent *expected_segment; @@ -101,6 +101,10 @@ struct _GstValidatePadMonitor { GstStructure *pending_setcaps_fields; + GstCaps * last_refused_caps; + GstCaps * last_query_filter; + GstCaps * last_query_res; + /* tracked data */ GstSegment segment; GstClockTime current_timestamp; diff --git a/validate/gst/validate/gst-validate-pipeline-monitor.c b/validate/gst/validate/gst-validate-pipeline-monitor.c index d47186aaed..443ee66680 100644 --- a/validate/gst/validate/gst-validate-pipeline-monitor.c +++ b/validate/gst/validate/gst-validate-pipeline-monitor.c @@ -26,6 +26,7 @@ #include "gst-validate-internal.h" #include "gst-validate-pipeline-monitor.h" +#include "gst-validate-pad-monitor.h" #include "gst-validate-monitor-factory.h" #define PRINT_POSITION_TIMEOUT 250 @@ -37,6 +38,15 @@ * TODO */ +typedef struct +{ + gint caps_struct_num; + gint filter_caps_struct_num; + GString *str; + GstStructure *filter; + gboolean found; +} StructureIncompatibleFieldsInfo; + enum { PROP_LAST @@ -112,24 +122,270 @@ print_position (GstValidateMonitor * monitor) return TRUE; } +static void +_check_pad_query_failures (GstPad * pad, GString * str, + GstValidatePadMonitor ** last_query_caps_fail_monitor, + GstValidatePadMonitor ** last_refused_caps_monitor) +{ + GstValidatePadMonitor *monitor; + GstPad *ghost_target = NULL; + + if (GST_IS_GHOST_PAD (pad)) { + ghost_target = gst_ghost_pad_get_target (GST_GHOST_PAD (pad)); + + pad = ghost_target; + } + + monitor = g_object_get_data (G_OBJECT (pad), "validate-monitor"); + + if (monitor->last_query_res && gst_caps_is_empty (monitor->last_query_res)) { + gst_object_replace ((GstObject **) last_query_caps_fail_monitor, + (GstObject *) monitor); + } + + if (monitor->last_refused_caps) + gst_object_replace ((GstObject **) last_refused_caps_monitor, + (GstObject *) monitor); + + if (ghost_target) + gst_object_unref (ghost_target); +} + +static void +_gather_pad_negotiation_details (GstPad * pad, GString * str, + GstValidatePadMonitor ** last_query_caps_fail_monitor, + GstValidatePadMonitor ** last_refused_caps_monitor) +{ + GList *tmp; + GstElement *next; + GstPad *peer = gst_pad_get_peer (pad); + + _check_pad_query_failures (pad, str, last_query_caps_fail_monitor, + last_refused_caps_monitor); + _check_pad_query_failures (peer, str, last_query_caps_fail_monitor, + last_refused_caps_monitor); + + next = GST_ELEMENT (gst_pad_get_parent (peer)); + GST_OBJECT_LOCK (next); + for (tmp = next->srcpads; tmp; tmp = tmp->next) + _gather_pad_negotiation_details (tmp->data, str, + last_query_caps_fail_monitor, last_refused_caps_monitor); + GST_OBJECT_UNLOCK (next); + + gst_object_unref (peer); + gst_object_unref (next); +} + +static gboolean +_find_structure_incompatible_fields (GQuark field_id, const GValue * value, + StructureIncompatibleFieldsInfo * info) +{ + gchar *value_str, *filter_str; + GValue intersect = { 0, }; + const GValue *filter_value = gst_structure_id_get_value (info->filter, + field_id); + + if (!filter_value) + return TRUE; + + value_str = gst_value_serialize (value); + filter_str = gst_value_serialize (filter_value); + + if (!gst_value_can_intersect (value, filter_value)) { + info->found = TRUE; + g_string_append_printf (info->str, + "\n -> Field '%s' downstream value from structure %d '(%s)%s' can't intersect with" + " filter value from structure number %d '(%s)%s' because of their types.", + g_quark_to_string (field_id), info->caps_struct_num, + G_VALUE_TYPE_NAME (value), value_str, info->filter_caps_struct_num, + G_VALUE_TYPE_NAME (filter_value), filter_str); + + return TRUE; + } + + if (gst_value_intersect (&intersect, value, filter_value)) { + g_value_reset (&intersect); + + return TRUE; + } + + info->found = TRUE; + g_string_append_printf (info->str, + "\n -> Field '%s' downstream value from structure %d '(%s)%s' can't intersect with" + " filter value from structure number %d '(%s)%s'", + g_quark_to_string (field_id), info->caps_struct_num, + G_VALUE_TYPE_NAME (value), value_str, info->filter_caps_struct_num, + G_VALUE_TYPE_NAME (filter_value), filter_str); + + g_free (value_str); + g_free (filter_str); + + return TRUE; +} + +static void +_append_query_caps_failure_details (GstValidatePadMonitor * monitor, + GString * str) +{ + gint i, j; + GstCaps *filter = gst_caps_copy (monitor->last_query_filter); + GstCaps *possible_caps = gst_pad_query_caps (monitor->pad, NULL); + const gchar *filter_name, *possible_name; + GstStructure *filter_struct, *possible_struct; + + g_string_append_printf (str, + "\n Caps negotiation failed starting from pad '%s'" + " as the QUERY_CAPS returned EMPTY caps for the following possible reasons:", + gst_validate_reporter_get_name (GST_VALIDATE_REPORTER (monitor))); + + for (i = 0; i < gst_caps_get_size (possible_caps); i++) { + possible_struct = gst_caps_get_structure (possible_caps, i); + possible_name = gst_structure_get_name (possible_struct); + + for (j = 0; j < gst_caps_get_size (filter); j++) { + StructureIncompatibleFieldsInfo info = { + .caps_struct_num = i, + .filter_caps_struct_num = j, + .str = str, + .found = FALSE + }; + + info.filter = filter_struct = gst_caps_get_structure (filter, j); + filter_name = gst_structure_get_name (filter_struct); + + if (g_strcmp0 (possible_name, filter_name)) { + g_string_append_printf (str, + "\n -> Downstream caps struct %d name '%s' differs from " + "filter caps struct %d name '%s'", + i, possible_name, j, filter_name); + + continue; + } + + gst_structure_foreach (possible_struct, + (GstStructureForeachFunc) _find_structure_incompatible_fields, &info); + } + } + + gst_caps_unref (possible_caps); + gst_caps_unref (filter); + +} + +static gboolean +_append_accept_caps_failure_details (GstValidatePadMonitor * monitor, + GString * str) +{ + gint i, j; + GstCaps *refused_caps = gst_caps_copy (monitor->last_refused_caps); + GstCaps *possible_caps = gst_pad_query_caps (monitor->pad, NULL); + gchar *caps_str = gst_caps_to_string (monitor->last_refused_caps); + StructureIncompatibleFieldsInfo info = { + .str = str, + .found = FALSE + }; + + g_string_append_printf (str, + "\n Caps negotiation failed at pad '%s' as it refused caps: %s", + gst_validate_reporter_get_name (GST_VALIDATE_REPORTER (monitor)), + caps_str); + g_free (caps_str); + + for (i = 0; i < gst_caps_get_size (refused_caps); i++) { + GstStructure *refused_struct = gst_caps_get_structure (refused_caps, i); + const gchar *filter_name; + const gchar *refused_name = gst_structure_get_name (refused_struct); + + for (j = 0; j < gst_caps_get_size (possible_caps); j++) { + info.caps_struct_num = i, + info.filter_caps_struct_num = j, + info.filter = gst_caps_get_structure (possible_caps, j); + + filter_name = gst_structure_get_name (info.filter); + if (g_strcmp0 (refused_name, filter_name)) { + g_string_append_printf (str, + "\n -> Downstream caps struct %d name '%s' differs from " + "filter caps struct %d name '%s'", i, refused_name, j, filter_name); + + continue; + } + + gst_structure_foreach (refused_struct, + (GstStructureForeachFunc) _find_structure_incompatible_fields, &info); + } + } + + gst_caps_unref (possible_caps); + + return TRUE; +} + +static gchar * +_generate_not_negotiated_error_report (GstMessage * msg) +{ + GString *str; + GList *tmp; + GstElement *element = GST_ELEMENT (GST_MESSAGE_SRC (msg)); + GstValidatePadMonitor *last_query_caps_fail_monitor = NULL, + *last_refused_caps_monitor = NULL; + + str = g_string_new (NULL); + g_string_append_printf (str, "Error message posted by: %s", + GST_OBJECT_NAME (element)); + + GST_OBJECT_LOCK (element); + for (tmp = element->srcpads; tmp; tmp = tmp->next) + _gather_pad_negotiation_details (tmp->data, str, + &last_query_caps_fail_monitor, &last_refused_caps_monitor); + GST_OBJECT_UNLOCK (element); + + if (last_query_caps_fail_monitor) + _append_query_caps_failure_details (last_query_caps_fail_monitor, str); + else if (last_refused_caps_monitor) + _append_accept_caps_failure_details (last_refused_caps_monitor, str); + else { + GST_ERROR ("We should always be able to generate detailed report" + " about why negotiation failed, please report a bug against" + " gst-devtools:validate with this message and a way to reproduce."); + } + + gst_object_replace ((GstObject **) & last_query_caps_fail_monitor, NULL); + gst_object_replace ((GstObject **) & last_refused_caps_monitor, NULL); + + return g_string_free (str, FALSE); +} + static void _bus_handler (GstBus * bus, GstMessage * message, GstValidatePipelineMonitor * monitor) { GError *err = NULL; gchar *debug = NULL; + const GstStructure *details = NULL; + GstFlowReturn error_flow = GST_FLOW_OK; switch (GST_MESSAGE_TYPE (message)) { case GST_MESSAGE_ERROR: gst_message_parse_error (message, &err, &debug); + gst_message_parse_error_details (message, &details); if (g_error_matches (err, GST_CORE_ERROR, GST_CORE_ERROR_MISSING_PLUGIN)) { GST_VALIDATE_REPORT (monitor, MISSING_PLUGIN, "Error: %s -- Debug message: %s", err->message, debug); + } else if ((g_error_matches (err, GST_STREAM_ERROR, + GST_STREAM_ERROR_FAILED) && details + && gst_structure_get_int (details, "flow-return", &error_flow) + && error_flow == GST_FLOW_NOT_NEGOTIATED) + || g_error_matches (err, GST_STREAM_ERROR, GST_STREAM_ERROR_FORMAT)) { + gchar *report = _generate_not_negotiated_error_report (message); + + GST_VALIDATE_REPORT (monitor, NOT_NEGOTIATED, "%s", report); + g_free (report); } else { GST_VALIDATE_REPORT (monitor, ERROR_ON_BUS, "Got error: %s -- Debug message: %s", err->message, debug); } + GST_VALIDATE_MONITOR_LOCK (monitor); monitor->got_error = TRUE; GST_VALIDATE_MONITOR_UNLOCK (monitor); diff --git a/validate/gst/validate/gst-validate-report.c b/validate/gst/validate/gst-validate-report.c index 02a45cfd07..cf831dd25a 100644 --- a/validate/gst/validate/gst-validate-report.c +++ b/validate/gst/validate/gst-validate-report.c @@ -318,6 +318,9 @@ gst_validate_report_load_issues (void) REGISTER_VALIDATE_ISSUE (CRITICAL, MISSING_PLUGIN, _("a gstreamer plugin is missing and prevented Validate from running"), NULL); + REGISTER_VALIDATE_ISSUE (CRITICAL, NOT_NEGOTIATED, + _("a NOT NEGOTIATED message has been emitted on the bus."), + NULL); REGISTER_VALIDATE_ISSUE (WARNING, WARNING_ON_BUS, _("We got a WARNING message on the bus"), NULL); REGISTER_VALIDATE_ISSUE (CRITICAL, ERROR_ON_BUS, diff --git a/validate/gst/validate/gst-validate-report.h b/validate/gst/validate/gst-validate-report.h index 2617024f95..b7713f675a 100644 --- a/validate/gst/validate/gst-validate-report.h +++ b/validate/gst/validate/gst-validate-report.h @@ -104,6 +104,7 @@ typedef enum { #define ALLOCATION_FAILURE _QUARK("runtime::allocation-failure") #define MISSING_PLUGIN _QUARK("runtime::missing-plugin") +#define NOT_NEGOTIATED _QUARK("runtime::not-negotiated") #define WARNING_ON_BUS _QUARK("runtime::warning-on-bus") #define ERROR_ON_BUS _QUARK("runtime::error-on-bus") @@ -164,7 +165,7 @@ struct _GstValidateReport { /* timestamp: The time at which this issue happened since * the process start (to stay in sync with gst logging) */ GstClockTime timestamp; - + /* message: issue-specific message. Gives more detail on the actual * issue. Can be NULL */ gchar *message;