From 3baba76c772c093b49ff61a54dc26730c9d188c2 Mon Sep 17 00:00:00 2001 From: Wim Taymans Date: Thu, 11 Jan 2024 12:05:29 +0100 Subject: [PATCH] pulse-server: improve message debug Add prefix to messages to mark sent and received messages. Send mem debug to log instead of stderr. Log the complete message and debug the command. --- src/modules/module-protocol-pulse/client.c | 2 +- src/modules/module-protocol-pulse/message.c | 60 ++++++++++++--------- src/modules/module-protocol-pulse/message.h | 2 +- src/modules/module-protocol-pulse/server.c | 2 +- 4 files changed, 39 insertions(+), 27 deletions(-) diff --git a/src/modules/module-protocol-pulse/client.c b/src/modules/module-protocol-pulse/client.c index 5a791485b..657d4a3b3 100644 --- a/src/modules/module-protocol-pulse/client.c +++ b/src/modules/module-protocol-pulse/client.c @@ -236,7 +236,7 @@ static int client_try_flush_messages(struct client *client) } else { if (m->channel == SPA_ID_INVALID && pw_log_topic_custom_enabled(SPA_LOG_LEVEL_INFO, pulse_conn)) - message_dump(SPA_LOG_LEVEL_INFO, m); + message_dump(SPA_LOG_LEVEL_INFO, ">>", m); message_free(m, true, false); client->out_index = 0; continue; diff --git a/src/modules/module-protocol-pulse/message.c b/src/modules/module-protocol-pulse/message.c index 5e781a75a..38d00d6b1 100644 --- a/src/modules/module-protocol-pulse/message.c +++ b/src/modules/module-protocol-pulse/message.c @@ -8,8 +8,10 @@ #include #include #include +#include #include +#include "commands.h" #include "defs.h" #include "format.h" #include "internal.h" @@ -643,12 +645,16 @@ int message_put(struct message *m, ...) return 0; } -int message_dump(enum spa_log_level level, struct message *m) +int message_dump(enum spa_log_level level, const char *prefix, struct message *m) { int res; uint32_t i, offset = m->offset, o; + struct spa_debug_log_ctx ctx = SPA_LOGF_DEBUG_INIT(pw_log_get(), level, + PW_LOG_TOPIC_DEFAULT, __FILE__, __LINE__, __func__ ); - pw_log(level, "message: len:%d alloc:%u", m->length, m->allocated); + m->offset = 0; + + pw_log(level, "%s message: len:%d alloc:%u", prefix, m->length, m->allocated); while (true) { uint8_t tag; @@ -662,18 +668,18 @@ int message_dump(enum spa_log_level level, struct message *m) char *val; if ((res = read_string(m, &val)) < 0) return res; - pw_log(level, "%u: string: '%s'", o, val); + pw_log(level, "%s %u: string: '%s'", prefix, o, val); break; } case TAG_STRING_NULL: - pw_log(level, "%u: string: NULL", o); + pw_log(level, "%s %u: string: NULL", prefix, o); break; case TAG_U8: { uint8_t val; if ((res = read_u8(m, &val)) < 0) return res; - pw_log(level, "%u: u8: %u", o, val); + pw_log(level, "%s %u: u8: %u", prefix, o, val); break; } case TAG_U32: @@ -681,7 +687,13 @@ int message_dump(enum spa_log_level level, struct message *m) uint32_t val; if ((res = read_u32(m, &val)) < 0) return res; - pw_log(level, "%u: u32: %u", o, val); + if (o == 0) { + pw_log(level, "%s %u: u32: %u (command %s)", + prefix, o, val, + val < COMMAND_MAX ? commands[val].name : "INVALID"); + } else { + pw_log(level, "%s %u: u32: %u", prefix, o, val); + } break; } case TAG_S64: @@ -689,7 +701,7 @@ int message_dump(enum spa_log_level level, struct message *m) uint64_t val; if ((res = read_u64(m, &val)) < 0) return res; - pw_log(level, "%u: s64: %"PRIi64"", o, (int64_t)val); + pw_log(level, "%s %u: s64: %"PRIi64"", prefix, o, (int64_t)val); break; } case TAG_U64: @@ -697,7 +709,7 @@ int message_dump(enum spa_log_level level, struct message *m) uint64_t val; if ((res = read_u64(m, &val)) < 0) return res; - pw_log(level, "%u: u64: %"PRIu64"", o, val); + pw_log(level, "%s %u: u64: %"PRIu64"", prefix, o, val); break; } case TAG_USEC: @@ -705,7 +717,7 @@ int message_dump(enum spa_log_level level, struct message *m) uint64_t val; if ((res = read_u64(m, &val)) < 0) return res; - pw_log(level, "%u: u64: %"PRIu64"", o, val); + pw_log(level, "%s %u: u64: %"PRIu64"", prefix, o, val); break; } case TAG_SAMPLE_SPEC: @@ -713,7 +725,7 @@ int message_dump(enum spa_log_level level, struct message *m) struct sample_spec ss; if ((res = read_sample_spec(m, &ss)) < 0) return res; - pw_log(level, "%u: ss: format:%s rate:%d channels:%u", o, + pw_log(level, "%s %u: ss: format:%s rate:%d channels:%u", prefix, o, format_id2name(ss.format), ss.rate, ss.channels); break; @@ -724,21 +736,21 @@ int message_dump(enum spa_log_level level, struct message *m) size_t len; if ((res = read_arbitrary(m, &mem, &len)) < 0) return res; - spa_debug_mem(0, mem, len); + spa_debugc_mem(&ctx.ctx, 0, mem, len); break; } case TAG_BOOLEAN_TRUE: - pw_log(level, "%u: bool: true", o); + pw_log(level, "%s %u: bool: true", prefix, o); break; case TAG_BOOLEAN_FALSE: - pw_log(level, "%u: bool: false", o); + pw_log(level, "%s %u: bool: false", prefix, o); break; case TAG_TIMEVAL: { struct timeval tv; if ((res = read_timeval(m, &tv)) < 0) return res; - pw_log(level, "%u: timeval: %lu:%lu", o, tv.tv_sec, tv.tv_usec); + pw_log(level, "%s %u: timeval: %lu:%lu", prefix, o, tv.tv_sec, tv.tv_usec); break; } case TAG_CHANNEL_MAP: @@ -746,9 +758,9 @@ int message_dump(enum spa_log_level level, struct message *m) struct channel_map map; if ((res = read_channel_map(m, &map)) < 0) return res; - pw_log(level, "%u: channelmap: channels:%u", o, map.channels); + pw_log(level, "%s %u: channelmap: channels:%u", prefix, o, map.channels); for (i = 0; i < map.channels; i++) - pw_log(level, " %d: %s", i, channel_id2name(map.map[i])); + pw_log(level, "%s %d: %s", prefix, i, channel_id2name(map.map[i])); break; } case TAG_CVOLUME: @@ -756,9 +768,9 @@ int message_dump(enum spa_log_level level, struct message *m) struct volume vol; if ((res = read_cvolume(m, &vol)) < 0) return res; - pw_log(level, "%u: cvolume: channels:%u", o, vol.channels); + pw_log(level, "%s %u: cvolume: channels:%u", prefix, o, vol.channels); for (i = 0; i < vol.channels; i++) - pw_log(level, " %d: %f", i, vol.values[i]); + pw_log(level, "%s %d: %f", prefix, i, vol.values[i]); break; } case TAG_PROPLIST: @@ -767,9 +779,9 @@ int message_dump(enum spa_log_level level, struct message *m) const struct spa_dict_item *it; res = read_props(m, props, false); if (res >= 0) { - pw_log(level, "%u: props: n_items:%u", o, props->dict.n_items); + pw_log(level, "%s %u: props: n_items:%u", prefix, o, props->dict.n_items); spa_dict_for_each(it, &props->dict) - pw_log(level, " '%s': '%s'", it->key, it->value); + pw_log(level, "%s '%s': '%s'", prefix, it->key, it->value); } pw_properties_free(props); if (res < 0) @@ -781,7 +793,7 @@ int message_dump(enum spa_log_level level, struct message *m) float vol; if ((res = read_volume(m, &vol)) < 0) return res; - pw_log(level, "%u: volume: %f", o, vol); + pw_log(level, "%s %u: volume: %f", prefix, o, vol); break; } case TAG_FORMAT_INFO: @@ -790,11 +802,11 @@ int message_dump(enum spa_log_level level, struct message *m) const struct spa_dict_item *it; if ((res = read_format_info(m, &info)) < 0) return res; - pw_log(level, "%u: format-info: enc:%s n_items:%u", - o, format_encoding2name(info.encoding), + pw_log(level, "%s %u: format-info: enc:%s n_items:%u", + prefix, o, format_encoding2name(info.encoding), info.props->dict.n_items); spa_dict_for_each(it, &info.props->dict) - pw_log(level, " '%s': '%s'", it->key, it->value); + pw_log(level, "%s '%s': '%s'", prefix, it->key, it->value); break; } } diff --git a/src/modules/module-protocol-pulse/message.h b/src/modules/module-protocol-pulse/message.h index 0c3f1c392..1ab5bc7c3 100644 --- a/src/modules/module-protocol-pulse/message.h +++ b/src/modules/module-protocol-pulse/message.h @@ -50,6 +50,6 @@ struct message *message_alloc(struct impl *impl, uint32_t channel, uint32_t size void message_free(struct message *msg, bool dequeue, bool destroy); int message_get(struct message *m, ...); int message_put(struct message *m, ...); -int message_dump(enum spa_log_level level, struct message *m); +int message_dump(enum spa_log_level level, const char *prefix, struct message *m); #endif /* PULSE_SERVER_MESSAGE_H */ diff --git a/src/modules/module-protocol-pulse/server.c b/src/modules/module-protocol-pulse/server.c index 24198b659..adcd60bbb 100644 --- a/src/modules/module-protocol-pulse/server.c +++ b/src/modules/module-protocol-pulse/server.c @@ -71,7 +71,7 @@ static int handle_packet(struct client *client, struct message *msg) if (pw_log_topic_custom_enabled(SPA_LOG_LEVEL_INFO, pulse_conn)) { pw_log_debug("client %p: command:%s", client, commands[command].name); - message_dump(SPA_LOG_LEVEL_INFO, msg); + message_dump(SPA_LOG_LEVEL_INFO, "<<", msg); } const struct command *cmd = &commands[command];