From f02c33964542b6fa6597fd5ae2c17563718408eb Mon Sep 17 00:00:00 2001 From: Wim Taymans Date: Thu, 7 May 2020 15:47:52 +0200 Subject: [PATCH] Improve debug Dump enum_params of failed format and buffer negotiation to error log. --- src/pipewire/buffers.c | 24 +++-- src/pipewire/context.c | 46 +++++++--- src/pipewire/filter.c | 4 +- src/pipewire/impl-link.c | 31 ++++--- src/pipewire/log.c | 187 +++++++++++++++++++++++++++++++++++++++ src/pipewire/private.h | 19 +++- src/pipewire/stream.c | 4 +- 7 files changed, 278 insertions(+), 37 deletions(-) diff --git a/src/pipewire/buffers.c b/src/pipewire/buffers.c index c0b956a82..5228394f3 100644 --- a/src/pipewire/buffers.c +++ b/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); } diff --git a/src/pipewire/context.c b/src/pipewire/context.c index d6e42e69a..fc8a5b45d 100644 --- a/src/pipewire/context.c +++ b/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, ¶m, &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; } diff --git a/src/pipewire/filter.c b/src/pipewire/filter.c index 74a0252ac..85eb6245f 100644 --- a/src/pipewire/filter.c +++ b/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, ¶m, param ? 1 : 0)) < 0) return res; diff --git a/src/pipewire/impl-link.c b/src/pipewire/impl-link.c index 91f0c851c..d4be9a45c 100644 --- a/src/pipewire/impl-link.c +++ b/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); - } + if (current) + 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); - } + if (current) + 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; diff --git a/src/pipewire/log.c b/src/pipewire/log.c index bb9332a6e..59ffd2f05 100644 --- a/src/pipewire/log.c +++ b/src/pipewire/log.c @@ -24,7 +24,13 @@ #include +#include +#include +#include +#include + #include +#include 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)); + } +} diff --git a/src/pipewire/private.h b/src/pipewire/private.h index 9c0c8f850..6ac36f48b 100644 --- a/src/pipewire/private.h +++ b/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 diff --git a/src/pipewire/stream.c b/src/pipewire/stream.c index 609313207..7b10c4e71 100644 --- a/src/pipewire/stream.c +++ b/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, ¶m, param ? 1 : 0)) < 0) return res;