Improve debug

Dump enum_params of failed format and buffer negotiation to error log.

src/pipewire/buffers.c

@@ -182,8 +182,7 @@ param_filter(struct pw_buffers *this,
 				break;
 		}
 
-		if (pw_log_level_enabled(SPA_LOG_LEVEL_DEBUG) && iparam != NULL)
-			spa_debug_pod(2, NULL, iparam);
+		pw_log_pod(SPA_LOG_LEVEL_DEBUG, iparam);
 
 		for (oidx = 0;;) {
 			pw_log_debug(NAME" %p: output param %d id:%d", this, oidx, id);
@@ -195,8 +194,7 @@ param_filter(struct pw_buffers *this,
 			if (out_res < 1)
 				break;
 
-			if (pw_log_level_enabled(SPA_LOG_LEVEL_DEBUG))
-				spa_debug_pod(2, NULL, oparam);
+			pw_log_pod(SPA_LOG_LEVEL_DEBUG, oparam);
 			num++;
 		}
 		if (out_res == -ENOENT && iparam) {
@@ -212,7 +210,11 @@ param_filter(struct pw_buffers *this,
 	if (num == 0) {
 		if (out_res == -ENOENT && in_res == -ENOENT)
 			return 0;
-		return in_res < 0 ? in_res : out_res < 0 ? out_res : -EINVAL;
+		if (in_res < 0)
+			return in_res;
+		if (out_res < 0)
+			return out_res;
+		return -EINVAL;
 	}
 	return num;
 }
@@ -250,8 +252,15 @@ int pw_buffers_negotiate(struct pw_context *context, uint32_t flags,
 	int res;
 
 	res = param_filter(result, &input, &output, SPA_PARAM_Buffers, &b);
-	if (res < 0)
+	if (res < 0) {
+		pw_context_debug_port_params(context, input.node, input.direction,
+				input.port_id, SPA_PARAM_Buffers,
+				"input param", res);
+		pw_context_debug_port_params(context, output.node, output.direction,
+				output.port_id, SPA_PARAM_Buffers,
+				"output param", res);
 		return res;
+	}
 	n_params = res;
 	if ((res = param_filter(result, &input, &output, SPA_PARAM_Meta, &b)) > 0)
 		n_params += res;
@@ -261,8 +270,7 @@ int pw_buffers_negotiate(struct pw_context *context, uint32_t flags,
 		params[i] = SPA_MEMBER(buffer, offset, struct spa_pod);
 		spa_pod_fixate(params[i]);
 		pw_log_debug(NAME" %p: fixated param %d:", result, i);
-		if (pw_log_level_enabled(SPA_LOG_LEVEL_DEBUG))
-			spa_debug_pod(2, NULL, params[i]);
+		pw_log_pod(SPA_LOG_LEVEL_DEBUG, params[i]);
 		offset += SPA_ROUND_UP_N(SPA_POD_SIZE(params[i]), 8);
 	}
 

src/pipewire/context.c

@@ -587,6 +587,37 @@ struct pw_impl_port *pw_context_find_port(struct pw_context *context,
 	return best;
 }
 
+int pw_context_debug_port_params(struct pw_context *this,
+		struct spa_node *node, enum spa_direction direction,
+		uint32_t port_id, uint32_t id, const char *debug, int err)
+{
+	struct spa_pod_builder b = { 0 };
+	uint8_t buffer[4096];
+	uint32_t state;
+	struct spa_pod *param;
+	int res;
+
+	pw_log_error("params %s: %d:%d (%s) %s",
+			spa_debug_type_find_name(spa_type_param, id),
+			direction, port_id, debug, spa_strerror(err));
+
+        state = 0;
+        while (true) {
+                spa_pod_builder_init(&b, buffer, sizeof(buffer));
+                res = spa_node_port_enum_params_sync(node,
+                                       direction, port_id,
+                                       id, &state,
+                                       NULL, &param, &b);
+                if (res != 1) {
+			if (res < 0)
+				pw_log_error("  error: %s", spa_strerror(res));
+                        break;
+		}
+                pw_log_pod(SPA_LOG_LEVEL_ERROR, param);
+        }
+        return 0;
+}
+
 /** Find a common format between two ports
  *
  * \param context a context object
@@ -647,8 +678,7 @@ int pw_context_find_format(struct pw_context *context,
 			goto error;
 		}
 		pw_log_debug(NAME" %p: Got output format:", context);
-		if (pw_log_level_enabled(SPA_LOG_LEVEL_DEBUG))
-			spa_debug_format(2, NULL, filter);
+		pw_log_format(SPA_LOG_LEVEL_DEBUG, filter);
 
 		if ((res = spa_node_port_enum_params_sync(input->node->node,
 						     input->direction, input->port_id,
@@ -674,8 +704,7 @@ int pw_context_find_format(struct pw_context *context,
 			goto error;
 		}
 		pw_log_debug(NAME" %p: Got input format:", context);
-		if (pw_log_level_enabled(SPA_LOG_LEVEL_DEBUG))
-			spa_debug_format(2, NULL, filter);
+		pw_log_format(SPA_LOG_LEVEL_DEBUG, filter);
 
 		if ((res = spa_node_port_enum_params_sync(output->node->node,
 						     output->direction, output->port_id,
@@ -707,8 +736,7 @@ int pw_context_find_format(struct pw_context *context,
 			goto error;
 		}
 		pw_log_debug(NAME" %p: enum output %d with filter: %p", context, oidx, filter);
-		if (pw_log_level_enabled(SPA_LOG_LEVEL_DEBUG))
-			spa_debug_format(2, NULL, filter);
+		pw_log_format(SPA_LOG_LEVEL_DEBUG, filter);
 
 		if ((res = spa_node_port_enum_params_sync(output->node->node,
 						     output->direction, output->port_id,
@@ -723,18 +751,16 @@ int pw_context_find_format(struct pw_context *context,
 		}
 
 		pw_log_debug(NAME" %p: Got filtered:", context);
-		if (pw_log_level_enabled(SPA_LOG_LEVEL_DEBUG))
-			spa_debug_format(2, NULL, *format);
+		pw_log_format(SPA_LOG_LEVEL_DEBUG, *format);
 	} else {
 		res = -EBADF;
 		*error = spa_aprintf("error bad node state");
 		goto error;
 	}
 	return res;
-
 error:
 	if (res == 0)
-		res = -ENOENT;
+		res = -EINVAL;
 	return res;
 }
 

src/pipewire/filter.c

@@ -619,8 +619,8 @@ static int impl_port_set_param(void *object,
 	if ((port = get_port(impl, direction, port_id)) == NULL)
 		return -EINVAL;
 
-	if (param && pw_log_level_enabled(SPA_LOG_LEVEL_DEBUG))
-		spa_debug_pod(2, NULL, param);
+	if (param)
+		pw_log_pod(SPA_LOG_LEVEL_DEBUG, param);
 
 	if ((res = update_params(impl, port, id, &param, param ? 1 : 0)) < 0)
 		return res;

src/pipewire/impl-link.c

@@ -163,6 +163,7 @@ static void complete_paused(void *obj, void *data, int res, uint32_t id)
 
 static int do_negotiate(struct pw_impl_link *this)
 {
+	struct pw_context *context = this->context;
 	struct impl *impl = SPA_CONTAINER_OF(this, struct impl, this);
 	int res = -EIO, res2;
 	struct spa_pod *format = NULL, *current;
@@ -194,10 +195,17 @@ static int do_negotiate(struct pw_impl_link *this)
 	output = this->output;
 
 	/* find a common format for the ports */
-	if ((res = pw_context_find_format(this->context,
+	if ((res = pw_context_find_format(context,
 					output, input, NULL, 0, NULL,
-					&format, &b, &error)) < 0)
+					&format, &b, &error)) < 0) {
+		pw_context_debug_port_params(context, input->node->node, input->direction,
+				input->port_id, SPA_PARAM_EnumFormat,
+				"input format", res);
+		pw_context_debug_port_params(context, output->node->node, output->direction,
+				output->port_id, SPA_PARAM_EnumFormat,
+				"output format", res);
 		goto error;
+	}
 
 	format = spa_pod_copy(format);
 	spa_pod_fixate(format);
@@ -227,11 +235,9 @@ static int do_negotiate(struct pw_impl_link *this)
 		}
 		if (current == NULL || spa_pod_compare(current, format) != 0) {
 			pw_log_debug(NAME" %p: output format change, renegotiate", this);
-			if (pw_log_level_enabled(SPA_LOG_LEVEL_DEBUG)) {
 			if (current)
-					spa_debug_pod(2, NULL, current);
-				spa_debug_pod(2, NULL, format);
-			}
+				pw_log_pod(SPA_LOG_LEVEL_DEBUG, current);
+			pw_log_pod(SPA_LOG_LEVEL_DEBUG, format);
 			pw_impl_node_set_state(output->node, PW_NODE_STATE_SUSPENDED);
 			out_state = PW_IMPL_PORT_STATE_CONFIGURE;
 		}
@@ -263,11 +269,9 @@ static int do_negotiate(struct pw_impl_link *this)
 		}
 		if (current == NULL || spa_pod_compare(current, format) != 0) {
 			pw_log_debug(NAME" %p: input format change, renegotiate", this);
-			if (pw_log_level_enabled(SPA_LOG_LEVEL_DEBUG)) {
 			if (current)
-					spa_debug_pod(2, NULL, current);
-				spa_debug_pod(2, NULL, format);
-			}
+				pw_log_pod(SPA_LOG_LEVEL_DEBUG, current);
+			pw_log_pod(SPA_LOG_LEVEL_DEBUG, format);
 			pw_impl_node_set_state(input->node, PW_NODE_STATE_SUSPENDED);
 			in_state = PW_IMPL_PORT_STATE_CONFIGURE;
 		}
@@ -278,8 +282,7 @@ static int do_negotiate(struct pw_impl_link *this)
 	}
 
 	pw_log_debug(NAME" %p: doing set format %p", this, format);
-	if (pw_log_level_enabled(SPA_LOG_LEVEL_DEBUG))
-		spa_debug_format(2, NULL, format);
+	pw_log_pod(SPA_LOG_LEVEL_DEBUG, format);
 
 	SPA_POD_OBJECT_ID(format) = SPA_PARAM_Format;
 

src/pipewire/log.c

@@ -24,7 +24,13 @@
 
 #include <spa/support/log-impl.h>
 
+#include <spa/pod/pod.h>
+#include <spa/debug/types.h>
+#include <spa/pod/pod.h>
+#include <spa/pod/iter.h>
+
 #include <pipewire/log.h>
+#include <pipewire/private.h>
 
 SPA_LOG_IMPL(default_log);
 
@@ -154,3 +160,184 @@ pw_log_logv(enum spa_log_level level,
  * realtime threads
  * \memberof pw_log
  */
+
+struct log_ctx {
+	enum spa_log_level level;
+	const char *file;
+	int line;
+	const char *func;
+};
+
+#define _log(_c,fmt,...) pw_log_log(_c->level, _c->file, _c->line, _c->func,   \
+		"%*s" fmt, indent, "", ## __VA_ARGS__)
+
+static inline int
+log_pod_value(struct log_ctx *ctx, int indent, const struct spa_type_info *info,
+		uint32_t type, void *body, uint32_t size)
+{
+	switch (type) {
+	case SPA_TYPE_Bool:
+		_log(ctx, "Bool %s", (*(int32_t *) body) ? "true" : "false");
+		break;
+	case SPA_TYPE_Id:
+		_log(ctx, "Id %-8d (%s)", *(int32_t *) body,
+		       spa_debug_type_find_name(info, *(int32_t *) body));
+		break;
+	case SPA_TYPE_Int:
+		_log(ctx, "Int %d", *(int32_t *) body);
+		break;
+	case SPA_TYPE_Long:
+		_log(ctx, "Long %" PRIi64 "", *(int64_t *) body);
+		break;
+	case SPA_TYPE_Float:
+		_log(ctx, "Float %f", *(float *) body);
+		break;
+	case SPA_TYPE_Double:
+		_log(ctx, "Double %f", *(double *) body);
+		break;
+	case SPA_TYPE_String:
+		_log(ctx, "String \"%s\"", (char *) body);
+		break;
+	case SPA_TYPE_Fd:
+		_log(ctx, "Fd %d", *(int *) body);
+		break;
+	case SPA_TYPE_Pointer:
+	{
+		struct spa_pod_pointer_body *b = (struct spa_pod_pointer_body *)body;
+		_log(ctx, "Pointer %s %p",
+		       spa_debug_type_find_name(SPA_TYPE_ROOT, b->type), b->value);
+		break;
+	}
+	case SPA_TYPE_Rectangle:
+	{
+		struct spa_rectangle *r = (struct spa_rectangle *)body;
+		_log(ctx, "Rectangle %dx%d", r->width, r->height);
+		break;
+	}
+	case SPA_TYPE_Fraction:
+	{
+		struct spa_fraction *f = (struct spa_fraction *)body;
+		_log(ctx, "Fraction %d/%d", f->num, f->denom);
+		break;
+	}
+	case SPA_TYPE_Bitmap:
+		_log(ctx, "Bitmap");
+		break;
+	case SPA_TYPE_Array:
+	{
+		struct spa_pod_array_body *b = (struct spa_pod_array_body *)body;
+		void *p;
+		const struct spa_type_info *ti = spa_debug_type_find(SPA_TYPE_ROOT, b->child.type);
+
+		_log(ctx, "Array: child.size %d, child.type %s", b->child.size,
+				ti ? ti->name : "unknown");
+
+		SPA_POD_ARRAY_BODY_FOREACH(b, size, p)
+			log_pod_value(ctx, indent + 2, info, b->child.type, p, b->child.size);
+		break;
+	}
+	case SPA_TYPE_Choice:
+	{
+		struct spa_pod_choice_body *b = (struct spa_pod_choice_body *)body;
+		void *p;
+		const struct spa_type_info *ti = spa_debug_type_find(spa_type_choice, b->type);
+
+		_log(ctx, "Choice: type %s, flags %08x %d %d",
+		       ti ? ti->name : "unknown", b->flags, size, b->child.size);
+
+		SPA_POD_CHOICE_BODY_FOREACH(b, size, p)
+			log_pod_value(ctx, indent + 2, info, b->child.type, p, b->child.size);
+		break;
+	}
+	case SPA_TYPE_Struct:
+	{
+		struct spa_pod *b = (struct spa_pod *)body, *p;
+		_log(ctx, "Struct: size %d", size);
+		SPA_POD_FOREACH(b, size, p)
+			log_pod_value(ctx, indent + 2, info, p->type, SPA_POD_BODY(p), p->size);
+		break;
+	}
+	case SPA_TYPE_Object:
+	{
+		struct spa_pod_object_body *b = (struct spa_pod_object_body *)body;
+		struct spa_pod_prop *p;
+		const struct spa_type_info *ti, *ii;
+
+		ti = spa_debug_type_find(info, b->type);
+		ii = ti ? spa_debug_type_find(ti->values, 0) : NULL;
+		ii = ii ? spa_debug_type_find(ii->values, b->id) : NULL;
+
+		_log(ctx, "Object: size %d, type %s (%d), id %s (%d)", size,
+		       ti ? ti->name : "unknown", b->type, ii ? ii->name : "unknown", b->id);
+
+		info = ti ? ti->values : info;
+
+		indent += 2;
+		SPA_POD_OBJECT_BODY_FOREACH(b, size, p) {
+			ii = spa_debug_type_find(info, p->key);
+
+			_log(ctx, "Prop: key %s (%d), flags %08x",
+					ii ? ii->name : "unknown", p->key, p->flags);
+
+			log_pod_value(ctx, indent + 2, ii ? ii->values : NULL,
+					p->value.type,
+					SPA_POD_CONTENTS(struct spa_pod_prop, p),
+					p->value.size);
+		}
+		indent -= 2;
+		break;
+	}
+	case SPA_TYPE_Sequence:
+	{
+		struct spa_pod_sequence_body *b = (struct spa_pod_sequence_body *)body;
+		const struct spa_type_info *ti, *ii;
+		struct spa_pod_control *c;
+
+		ti = spa_debug_type_find(info, b->unit);
+
+		_log(ctx, "%*s" "Sequence: size %d, unit %s", indent, "", size,
+		       ti ? ti->name : "unknown");
+
+		indent +=2;
+		SPA_POD_SEQUENCE_BODY_FOREACH(b, size, c) {
+			ii = spa_debug_type_find(spa_type_control, c->type);
+
+			_log(ctx, "Control: offset %d, type %s",
+					c->offset, ii ? ii->name : "unknown");
+
+			log_pod_value(ctx, indent + 2, ii ? ii->values : NULL,
+					c->value.type,
+					SPA_POD_CONTENTS(struct spa_pod_control, c),
+					c->value.size);
+		}
+		indent -=2;
+		break;
+	}
+	case SPA_TYPE_Bytes:
+		_log(ctx, "Bytes");
+		break;
+	case SPA_TYPE_None:
+		_log(ctx, "None");
+		break;
+	default:
+		_log(ctx, "unhandled POD type %d", type);
+		break;
+	}
+	return 0;
+}
+
+void pw_log_log_object(enum spa_log_level level,
+	   const char *file,
+	   int line,
+	   const char *func,
+	   uint32_t flags, const void *object)
+{
+	struct log_ctx ctx = { level, file, line, func, };
+	if (flags & PW_LOG_OBJECT_POD) {
+		const struct spa_pod *pod = object;
+		log_pod_value(&ctx, 0, SPA_TYPE_ROOT,
+			SPA_POD_TYPE(pod),
+			SPA_POD_BODY(pod),
+			SPA_POD_BODY_SIZE(pod));
+	}
+}

src/pipewire/private.h

@@ -45,7 +45,7 @@ struct ucred {
 #endif
 
 #ifndef spa_debug
-#define spa_debug pw_log_trace
+#define spa_debug(...) pw_log_trace(__VA_ARGS__)
 #endif
 
 struct defaults {
@@ -983,6 +983,10 @@ pw_context_find_port(struct pw_context *context,
 		  struct spa_pod **format_filters,
 		  char **error);
 
+int pw_context_debug_port_params(struct pw_context *context,
+		struct spa_node *node, enum spa_direction direction,
+		uint32_t port_id, uint32_t id, const char *debug, int err);
+
 const struct pw_export_type *pw_context_find_export_type(struct pw_context *context, const char *type);
 
 int pw_proxy_init(struct pw_proxy *proxy, const char *type, uint32_t version);
@@ -1087,6 +1091,19 @@ void pw_control_destroy(struct pw_control *control);
 
 void pw_proxy_unref(struct pw_proxy *proxy);
 
+#define PW_LOG_OBJECT_POD	(1<<0)
+void pw_log_log_object(enum spa_log_level level, const char *file, int line,
+	   const char *func, uint32_t flags, const void *object);
+
+#define pw_log_object(lev,fl,obj)						\
+({										\
+	if (SPA_UNLIKELY(pw_log_level_enabled (lev)))				\
+		pw_log_log_object(lev,__FILE__,__LINE__,__func__,(fl),(obj));	\
+})
+
+#define pw_log_pod(lev,pod) pw_log_object(lev,PW_LOG_OBJECT_POD,pod)
+#define pw_log_format(lev,pod) pw_log_object(lev,PW_LOG_OBJECT_POD,pod)
+
 /** \endcond */
 
 #ifdef __cplusplus

src/pipewire/stream.c

@@ -616,8 +616,8 @@ static int impl_port_set_param(void *object,
 	pw_log_debug(NAME" %p: param id %d (%s) changed: %p", impl, id,
 			spa_debug_type_find_name(spa_type_param, id), param);
 
-	if (param && pw_log_level_enabled(SPA_LOG_LEVEL_DEBUG))
-		spa_debug_pod(2, NULL, param);
+	if (param)
+		pw_log_pod(SPA_LOG_LEVEL_DEBUG, param);
 
 	if ((res = update_params(impl, id, &param, param ? 1 : 0)) < 0)
 		return res;