improve debug

Improve log so that debug level 3 gives a reasonably readable overview
of what is going on.

11 files changed, 73 insertions, 47 deletions

diff --git a/src/examples/export-source.c b/src/examples/export-source.c
index 6e53c012..087f5725 100644
--- a/src/examples/export-source.c
+++ b/src/examples/export-source.c
@@ -339,7 +339,7 @@ static int impl_port_use_buffers(void *object,
 		}
 		b->id = i;
 		b->buffer = buffers[i];
-		pw_log_info("got buffer %d size %d", i, datas[0].maxsize);
+		pw_log_debug("got buffer %d size %d", i, datas[0].maxsize);
 		spa_list_append(&d->empty, &b->link);
 	}
 	d->n_buffers = n_buffers;
diff --git a/src/examples/media-session/policy-ep.c b/src/examples/media-session/policy-ep.c
index b6743012..dbb9bd78 100644
--- a/src/examples/media-session/policy-ep.c
+++ b/src/examples/media-session/policy-ep.c
@@ -419,14 +419,14 @@ static int rescan_endpoint(struct impl *impl, struct endpoint *ep)
 	find.ep = ep;
 	find.exclusive = exclusive;
 
-	pw_log_info(NAME " %p: exclusive:%d", impl, exclusive);
+	pw_log_debug(NAME " %p: exclusive:%d", impl, exclusive);
 
 	str = spa_dict_lookup(props, PW_KEY_ENDPOINT_TARGET);
 	if (str == NULL)
 		str = spa_dict_lookup(props, PW_KEY_NODE_TARGET);
 	if (str != NULL) {
 		uint32_t path_id = atoi(str);
-		pw_log_info(NAME " %p: target:%d", impl, path_id);
+		pw_log_debug(NAME " %p: target:%d", impl, path_id);
 
 		if ((obj = sm_media_session_find_object(impl->session, path_id)) != NULL) {
 			if (strcmp(obj->type, PW_TYPE_INTERFACE_Endpoint) == 0) {
diff --git a/src/examples/media-session/policy-node.c b/src/examples/media-session/policy-node.c
index 28a3c9a4..82696eb0 100644
--- a/src/examples/media-session/policy-node.c
+++ b/src/examples/media-session/policy-node.c
@@ -460,12 +460,12 @@ static int rescan_node(struct impl *impl, struct node *n)
 	find.target = n;
 	find.exclusive = exclusive;
 
-	pw_log_info(NAME " %p: exclusive:%d", impl, exclusive);
+	pw_log_debug(NAME " %p: exclusive:%d", impl, exclusive);
 
 	str = spa_dict_lookup(props, PW_KEY_NODE_TARGET);
 	if (str != NULL) {
 		uint32_t path_id = atoi(str);
-		pw_log_info(NAME " %p: target:%d", impl, path_id);
+		pw_log_debug(NAME " %p: target:%d", impl, path_id);
 
 		if ((obj = sm_media_session_find_object(impl->session, path_id)) != NULL) {
 			if (strcmp(obj->type, PW_TYPE_INTERFACE_Node) == 0) {
diff --git a/src/modules/module-client-node/v0/client-node.c b/src/modules/module-client-node/v0/client-node.c
index d6369017..4d3c8e07 100644
--- a/src/modules/module-client-node/v0/client-node.c
+++ b/src/modules/module-client-node/v0/client-node.c
@@ -437,7 +437,7 @@ do_update_port(struct node *this,
 	port = GET_PORT(this, direction, port_id);
 
 	if (!port->valid) {
-		spa_log_info(this->log, "node %p: adding port %d", this, port_id);
+		spa_log_debug(this->log, "node %p: adding port %d", this, port_id);
 		port->id = port_id;
 		port->direction = direction;
 		port->have_format = false;
@@ -454,7 +454,7 @@ do_update_port(struct node *this,
 
 		port->have_format = false;
 
-		spa_log_info(this->log, "node %p: port %u update %d params", this, port_id, n_params);
+		spa_log_debug(this->log, "node %p: port %u update %d params", this, port_id, n_params);
 		for (i = 0; i < port->n_params; i++)
 			free(port->params[i]);
 		port->n_params = n_params;
@@ -504,7 +504,7 @@ static void do_uninit_port(struct node *this, enum spa_direction direction, uint
 {
 	struct port *port;
 
-	spa_log_info(this->log, "node %p: removing port %d", this, port_id);
+	spa_log_debug(this->log, "node %p: removing port %d", this, port_id);
 
 	if (direction == SPA_DIRECTION_INPUT) {
 		port = GET_IN_PORT(this, port_id);
@@ -637,7 +637,7 @@ impl_node_port_set_io(void *object,
 
 	impl = this->impl;
 
-	spa_log_info(this->log, "node %p: port %d.%d set io %d %p", this,
+	spa_log_debug(this->log, "node %p: port %d.%d set io %d %p", this,
 			direction, port_id, id, data);
 
 	if (id == SPA_IO_Buffers) {
@@ -694,7 +694,7 @@ impl_node_port_use_buffers(void *object,
 	spa_return_val_if_fail(CHECK_PORT(this, direction, port_id), -EINVAL);
 
 	impl = this->impl;
-	spa_log_info(this->log, "node %p: use buffers %p %u", this, buffers, n_buffers);
+	spa_log_debug(this->log, "node %p: use buffers %p %u", this, buffers, n_buffers);
 
 	port = GET_PORT(this, direction, port_id);
 
@@ -1010,7 +1010,7 @@ client_node0_update(void *data,
 		this->info.max_output_ports = max_output_ports;
 	if (change_mask & PW_CLIENT_NODE0_UPDATE_PARAMS) {
 		uint32_t i;
-		spa_log_info(this->log, "node %p: update %d params", this, n_params);
+		spa_log_debug(this->log, "node %p: update %d params", this, n_params);
 
 		for (i = 0; i < this->n_params; i++)
 			free(this->params[i]);
@@ -1024,7 +1024,7 @@ client_node0_update(void *data,
 		spa_node_emit_info(&this->hooks, &this->info);
 	}
 
-	spa_log_info(this->log, "node %p: got node update max_in %u, max_out %u", this,
+	spa_log_debug(this->log, "node %p: got node update max_in %u, max_out %u", this,
 		     this->info.max_input_ports, this->info.max_output_ports);
 }
 
@@ -1041,7 +1041,7 @@ client_node0_port_update(void *data,
 	struct node *this = &impl->node;
 	bool remove;
 
-	spa_log_info(this->log, "node %p: got port update", this);
+	spa_log_debug(this->log, "node %p: got port update", this);
 	if (!CHECK_PORT_ID(this, direction, port_id))
 		return;
 
diff --git a/src/modules/module-protocol-native.c b/src/modules/module-protocol-native.c
index f9fa3e11..9b78c25c 100644
--- a/src/modules/module-protocol-native.c
+++ b/src/modules/module-protocol-native.c
@@ -1012,7 +1012,7 @@ create_server(struct pw_protocol *protocol,
 
 	pw_loop_add_hook(pw_context_get_main_loop(context), &s->hook, &impl_hooks, s);
 
-	pw_log_info(NAME" %p: created server %p", protocol, this);
+	pw_log_debug(NAME" %p: created server %p", protocol, this);
 
 	return s;
 }
diff --git a/src/modules/spa/spa-node.c b/src/modules/spa/spa-node.c
index 15ed04c1..f13c2757 100644
--- a/src/modules/spa/spa-node.c
+++ b/src/modules/spa/spa-node.c
@@ -187,7 +187,7 @@ setup_props(struct pw_context *context, struct spa_node *spa_node, struct pw_pro
 		if ((prop = spa_pod_find_prop(props, prop, type))) {
 			const char *value = pw_properties_get(pw_props, key);
 
-			pw_log_info("configure prop %s to %s", key, value);
+			pw_log_debug("configure prop %s to %s", key, value);
 
 			switch(prop->value.type) {
 			case SPA_TYPE_Bool:
diff --git a/src/pipewire/context.c b/src/pipewire/context.c
index d645fba5..1c1693bf 100644
--- a/src/pipewire/context.c
+++ b/src/pipewire/context.c
@@ -876,8 +876,8 @@ int pw_context_recalc_graph(struct pw_context *context)
 
 		if (n->rt.position && n->quantum_current != n->rt.position->clock.duration) {
 			n->rt.position->clock.duration = n->quantum_current;
-			pw_log_info(NAME" %p: new quantum %u for master '%s'", context,
-					n->quantum_current, n->name);
+			pw_log_info("(%s-%u) new quantum:%u",
+					n->name, n->info.id, n->quantum_current);
 		}
 
 		pw_log_debug(NAME" %p: master %p quantum:%u '%s'", context, n,
diff --git a/src/pipewire/impl-device.c b/src/pipewire/impl-device.c
index f9e6c682..01e89cd0 100644
--- a/src/pipewire/impl-device.c
+++ b/src/pipewire/impl-device.c
@@ -116,10 +116,11 @@ static void check_properties(struct pw_impl_device *device)
 {
 	const char *str;
 
-	if ((str = pw_properties_get(device->properties, PW_KEY_DEVICE_NAME))) {
+	if ((str = pw_properties_get(device->properties, PW_KEY_DEVICE_NAME)) &&
+	    (device->name == NULL || strcmp(str, device->name) != 0)) {
 		free(device->name);
 		device->name = strdup(str);
-		pw_log_info(NAME" %p: name '%s'", device, device->name);
+		pw_log_debug(NAME" %p: name '%s'", device, device->name);
 	}
 }
 
diff --git a/src/pipewire/impl-link.c b/src/pipewire/impl-link.c
index c4c40a92..6bb3fd3d 100644
--- a/src/pipewire/impl-link.c
+++ b/src/pipewire/impl-link.c
@@ -114,12 +114,17 @@ static void pw_impl_link_update_state(struct pw_impl_link *link, enum pw_link_st
 	if (state == old)
 		return;
 
+	pw_log_debug(NAME" %p: %s -> %s (%s)", link,
+		     pw_link_state_as_string(old),
+		     pw_link_state_as_string(state), error);
+
 	if (state == PW_LINK_STATE_ERROR) {
-		pw_log_error(NAME" %p: update state %s -> error (%s)", link,
-		     pw_link_state_as_string(old), error);
+		pw_log_error("(%s) %s -> error (%s)", link->name,
+				pw_link_state_as_string(old), error);
 	} else {
-		pw_log_debug(NAME" %p: update state %s -> %s", link,
-		     pw_link_state_as_string(old), pw_link_state_as_string(state));
+		pw_log_info("(%s) %s -> %s", link->name,
+				pw_link_state_as_string(old),
+				pw_link_state_as_string(state));
 	}
 
 	link->info.state = state;
@@ -1139,6 +1144,11 @@ struct pw_impl_link *pw_context_create_link(struct pw_context *context,
 		     output_node, output->port_id, this->rt.out_mix.port.port_id,
 		     input_node, input->port_id, this->rt.in_mix.port.port_id);
 
+	asprintf(&this->name, "%d.%d -> %d.%d",
+			output_node->info.id, output->port_id,
+			input_node->info.id, input->port_id);
+	pw_log_info("(%s) (%s) -> (%s)", this->name, output_node->name, input_node->name);
+
 	pw_impl_port_emit_link_added(output, this);
 	pw_impl_port_emit_link_added(input, this);
 
@@ -1272,6 +1282,7 @@ void pw_impl_link_destroy(struct pw_impl_link *link)
 	struct impl *impl = SPA_CONTAINER_OF(link, struct impl, this);
 
 	pw_log_debug(NAME" %p: destroy", impl);
+	pw_log_info("(%s) destroy", link->name);
 	pw_impl_link_emit_destroy(link);
 
 	pw_impl_link_deactivate(link);
@@ -1300,6 +1311,7 @@ void pw_impl_link_destroy(struct pw_impl_link *link)
 
 	pw_context_recalc_graph(link->context);
 
+	free(link->name);
 	free(link->info.format);
 	free(impl);
 }
diff --git a/src/pipewire/impl-node.c b/src/pipewire/impl-node.c
index 13473850..8ee90d60 100644
--- a/src/pipewire/impl-node.c
+++ b/src/pipewire/impl-node.c
@@ -195,8 +195,8 @@ static int start_node(struct pw_impl_node *this)
 				    &SPA_NODE_COMMAND_INIT(SPA_NODE_COMMAND_Start));
 
 	if (res < 0)
-		pw_log_error(NAME" %p: start node error %d: %s",
-				this, res, spa_strerror(res));
+		pw_log_error("(%s-%u) start node error %d: %s", this->name, this->info.id,
+				res, spa_strerror(res));
 
 	return res;
 }
@@ -296,11 +296,14 @@ static void node_update_state(struct pw_impl_node *node, enum pw_node_state stat
 	if (old == state)
 		return;
 
+	pw_log_debug(NAME" %p: (%s) %s -> %s (%s)", node, node->name,
+		     pw_node_state_as_string(old), pw_node_state_as_string(state), error);
+
 	if (state == PW_NODE_STATE_ERROR) {
-		pw_log_error(NAME" %p: update state from %s -> error (%s)", node,
+		pw_log_error("(%s-%u) %s -> error (%s)", node->name, node->info.id,
 		     pw_node_state_as_string(old), error);
 	} else {
-		pw_log_debug(NAME" %p: update state from %s -> %s", node,
+		pw_log_info("(%s-%u) %s -> %s", node->name, node->info.id,
 		     pw_node_state_as_string(old), pw_node_state_as_string(state));
 	}
 
@@ -673,8 +676,11 @@ int pw_impl_node_set_driver(struct pw_impl_node *node, struct pw_impl_node *driv
 	remove_segment_master(old, node->info.id);
 
 	node->master = node->driver && driver == node;
-	pw_log_info(NAME" %p: driver %p (%s) quantum:%u master:%u", node,
-			driver, driver->name, driver->quantum_current, node->master);
+	pw_log_debug(NAME" %p: driver %p quantum:%u master:%u", node,
+		driver, driver->quantum_current, node->master);
+	pw_log_info("(%s-%u) -> driver (%s-%d) quantum:%u",
+			node->name, node->info.id, driver->name,
+			driver->info.id, driver->quantum_current);
 
 	node->driver_node = driver;
 
@@ -715,14 +721,14 @@ static void check_properties(struct pw_impl_node *node)
 
 	if ((str = pw_properties_get(node->properties, PW_KEY_PRIORITY_MASTER))) {
 		node->priority_master = pw_properties_parse_int(str);
-		pw_log_info(NAME" %p: priority master %d", node, node->priority_master);
+		pw_log_debug(NAME" %p: priority master %d", node, node->priority_master);
 	}
 
 	if ((str = pw_properties_get(node->properties, PW_KEY_NODE_NAME)) &&
-	    (node->name == NULL || strcmp(str, node->name) != 0)) {
+	    (node->name == NULL || strcmp(node->name, str) != 0)) {
 		free(node->name);
 		node->name = strdup(str);
-		pw_log_info(NAME" %p: name '%s'", node, node->name);
+		pw_log_debug(NAME" %p: name '%s'", node, node->name);
 	}
 
 	if ((str = pw_properties_get(node->properties, PW_KEY_NODE_PAUSE_ON_IDLE)))
@@ -741,7 +747,7 @@ static void check_properties(struct pw_impl_node *node)
 		node->want_driver = false;
 
 	if (node->driver != driver) {
-		pw_log_info(NAME" %p: driver %d -> %d", node, node->driver, driver);
+		pw_log_debug(NAME" %p: driver %d -> %d", node, node->driver, driver);
 		node->driver = driver;
 		if (node->registered) {
 			if (driver)
@@ -759,8 +765,10 @@ static void check_properties(struct pw_impl_node *node)
 			quantum_size = flp2((num * context->defaults.clock_rate / denom));
 
 			if (quantum_size != node->quantum_size) {
-				pw_log_info(NAME" %p: latency '%s' quantum %u/%u",
+				pw_log_debug(NAME" %p: latency '%s' quantum %u/%u",
 						node, str, quantum_size, context->defaults.clock_rate);
+				pw_log_info("(%s-%u) quantum %u/%u", node->name, node->info.id,
+						quantum_size, context->defaults.clock_rate);
 				node->quantum_size = quantum_size;
 				do_recalc |= node->active;
 			}
@@ -796,9 +804,9 @@ static void dump_states(struct pw_impl_node *driver)
 		struct pw_node_activation_state *state = &a->state[0];
 		if (t->node == NULL)
 			continue;
-		pw_log_warn(NAME" %p (%s): state:%p pending:%d/%d s:%"PRIu64" a:%"PRIu64" f:%"PRIu64
+		pw_log_warn("(%s-%u) state:%p pending:%d/%d s:%"PRIu64" a:%"PRIu64" f:%"PRIu64
 				" waiting:%"PRIu64" process:%"PRIu64" status:%s sync:%d",
-				t->node, t->node->name, state,
+				t->node->name, t->node->info.id, state,
 				state->pending, state->required,
 				a->signal_time,
 				a->awake_time,
@@ -1318,7 +1326,8 @@ static void update_position(struct pw_impl_node *node, int all_ready)
 
 	if (a->position.state == SPA_IO_POSITION_STATE_STARTING) {
 		if (!all_ready && --a->sync_left == 0) {
-			pw_log_warn(NAME" %p: sync timeout, going to RUNNING", node);
+			pw_log_warn("(%s-%u) sync timeout, going to RUNNING",
+					node->name, node->info.id);
 			pw_context_driver_emit_timeout(node->context, node);
 			dump_states(node);
 			all_ready = true;
@@ -1348,8 +1357,9 @@ static int node_ready(void *data, int status)
 		uint64_t min_timeout = UINT64_MAX;
 
 		if (SPA_UNLIKELY(state->pending > 0)) {
-			pw_log_warn(NAME" %p: graph not finished: state:%p pending %d/%d",
-					node, state, state->pending, state->required);
+			pw_log_warn("(%s-%u) graph not finished: state:%p pending %d/%d",
+					node->name, node->info.id, state, state->pending,
+					state->required);
 			pw_context_driver_emit_incomplete(node->context, node);
 			dump_states(node);
 			node->rt.target.signal(node->rt.target.data);
@@ -1517,6 +1527,7 @@ void pw_impl_node_destroy(struct pw_impl_node *node)
 	node->active = false;
 
 	pw_log_debug(NAME" %p: destroy", impl);
+	pw_log_info("(%s-%u) destroy", node->name, node->info.id);
 	pw_impl_node_emit_destroy(node);
 
 	suspend_node(node);
diff --git a/src/pipewire/private.h b/src/pipewire/private.h
index a59698b2..629ae3ca 100644
--- a/src/pipewire/private.h
+++ b/src/pipewire/private.h
@@ -704,19 +704,21 @@ struct pw_control_link {
 
 struct pw_impl_link {
 	struct pw_context *context;		/**< context object */
-	struct spa_list link;		/**< link in context link_list */
-	struct pw_global *global;	/**< global for this link */
+	struct spa_list link;			/**< link in context link_list */
+	struct pw_global *global;		/**< global for this link */
 	struct spa_hook global_listener;
 
-        struct pw_link_info info;		/**< introspectable link info */
+	char *name;
+
+	struct pw_link_info info;		/**< introspectable link info */
 	struct pw_properties *properties;	/**< extra link properties */
 
-	struct spa_io_buffers *io;	/**< link io area */
+	struct spa_io_buffers *io;		/**< link io area */
 
 	struct pw_impl_port *output;		/**< output port */
-	struct spa_list output_link;	/**< link in output port links */
+	struct spa_list output_link;		/**< link in output port links */
 	struct pw_impl_port *input;		/**< input port */
-	struct spa_list input_link;	/**< link in input port links */
+	struct spa_list input_link;		/**< link in input port links */
 
 	struct spa_hook_list listener_list;
 
@@ -725,8 +727,8 @@ struct pw_impl_link {
 
 	struct {
 		struct pw_impl_port_mix out_mix;	/**< port added to the output mixer */
-		struct pw_impl_port_mix in_mix;	/**< port added to the input mixer */
-		struct pw_node_target target;	/**< target to trigger the input node */
+		struct pw_impl_port_mix in_mix;		/**< port added to the input mixer */
+		struct pw_node_target target;		/**< target to trigger the input node */
 	} rt;
 
 	void *user_data;