[DEBUG] Add debug logs for pipeline prepare failures

Add info-level logs to diagnose test failures:
- aria: Log format/rate/channels before validation
- ipc4: Log pipeline state during RESET transitions
- pipeline: Log component state during prepare

Signed-off-by: Tomasz Leman <tomasz.m.leman@intel.com>

Author: tmleman

src/audio/aria/aria.c

@@ -185,8 +185,7 @@ static int aria_prepare(struct processing_module *mod,
 	struct comp_buffer *source, *sink;
 	struct comp_dev *dev = mod->dev;
 	struct aria_data *cd = module_get_private_data(mod);
-
-	comp_info(dev, "aria_prepare()");
+	comp_info(dev, "entry: dev->state=%d", dev->state);
 
 	source = comp_dev_get_first_data_producer(dev);
 	sink = comp_dev_get_first_data_consumer(dev);
@@ -198,9 +197,21 @@ static int aria_prepare(struct processing_module *mod,
 	aria_set_stream_params(source, mod);
 	aria_set_stream_params(sink, mod);
 
+	/* Log detailed format information before validation */
+	comp_info(dev, "aria_prepare: source fmt=%d rate=%d channels=%d",
+		  audio_stream_get_valid_fmt(&source->stream),
+		  audio_stream_get_rate(&source->stream),
+		  audio_stream_get_channels(&source->stream));
+	comp_info(dev, "aria_prepare: sink fmt=%d rate=%d channels=%d",
+		  audio_stream_get_valid_fmt(&sink->stream),
+		  audio_stream_get_rate(&sink->stream),
+		  audio_stream_get_channels(&sink->stream));
+
 	if (audio_stream_get_valid_fmt(&source->stream) != SOF_IPC_FRAME_S24_4LE ||
 	    audio_stream_get_valid_fmt(&sink->stream) != SOF_IPC_FRAME_S24_4LE) {
-		comp_err(dev, "format is not supported");
+		comp_err(dev, "format is not supported: source_fmt=%d (expected=%d), sink_fmt=%d (expected=%d)",
+			 audio_stream_get_valid_fmt(&source->stream), SOF_IPC_FRAME_S24_4LE,
+			 audio_stream_get_valid_fmt(&sink->stream), SOF_IPC_FRAME_S24_4LE);
 		return -EINVAL;
 	}
 
@@ -209,7 +220,9 @@ static int aria_prepare(struct processing_module *mod,
 		return 0;
 	}
 
+	comp_info(dev, "calling comp_set_state: current state=%d", dev->state);
 	ret = comp_set_state(dev, COMP_TRIGGER_PREPARE);
+	comp_info(dev, "comp_set_state returned: ret=%d, new state=%d", ret, dev->state);
 	if (ret < 0)
 		return ret;
 

src/audio/pipeline/pipeline-params.c

@@ -262,8 +262,8 @@ static int pipeline_comp_prepare(struct comp_dev *current,
 	struct pipeline_data *ppl_data = ctx->comp_data;
 	int err;
 
-	pipe_dbg(current->pipeline, "pipeline_comp_prepare(), current->comp.id = 0x%x, dir = %u",
-		 dev_comp_id(current), dir);
+	pipe_info(current->pipeline, "pipeline_comp_prepare(), current->comp.id = 0x%x, dir = %u",
+		  dev_comp_id(current), dir);
 
 	if (!comp_is_single_pipeline(current, ppl_data->start)) {
 		/* ipc4 module is only prepared in its parent pipeline */
@@ -282,9 +282,14 @@ static int pipeline_comp_prepare(struct comp_dev *current,
 			return err;
 	}
 
+	pipe_info(current->pipeline, "calling comp_prepare() for comp 0x%x (state=%d)",
+		  dev_comp_id(current), current->state);
 	err = comp_prepare(current);
-	if (err < 0 || err == PPL_STATUS_PATH_STOP)
+	if (err < 0 || err == PPL_STATUS_PATH_STOP) {
+		pipe_err(current->pipeline, "comp_prepare() failed for comp 0x%x: err=%d",
+			 dev_comp_id(current), err);
 		return err;
+	}
 
 	return pipeline_for_each_comp(current, ctx, dir);
 }

src/ipc/ipc4/handler.c

@@ -160,11 +160,16 @@ static int ipc4_pcm_params(struct ipc_comp_dev *pcm_dev)
 	}
 
 	/* prepare pipeline audio params */
+	tr_info(&ipc_tr, "ipc: attempting to prepare pipe %d comp %d (state=%d)",
+		pcm_dev->cd->pipeline->pipeline_id,
+		pcm_dev->cd->pipeline->comp_id,
+		pcm_dev->cd->pipeline->status);
 	err = pipeline_prepare(pcm_dev->cd->pipeline, pcm_dev->cd);
 	if (err < 0) {
-		ipc_cmd_err(&ipc_tr, "ipc: pipe %d comp %d prepare failed %d",
+		ipc_cmd_err(&ipc_tr, "ipc: pipe %d comp %d prepare failed %d (state=%d)",
 			    pcm_dev->cd->pipeline->pipeline_id,
-			    pcm_dev->cd->pipeline->comp_id, err);
+			    pcm_dev->cd->pipeline->comp_id, err,
+			    pcm_dev->cd->pipeline->status);
 		goto error;
 	}
 
@@ -309,20 +314,29 @@ int ipc4_pipeline_prepare(struct ipc_comp_dev *ppl_icd, uint32_t cmd)
 		}
 		break;
 	case SOF_IPC4_PIPELINE_STATE_RESET:
+		tr_info(&ipc_tr, "pipeline %d: attempting RESET from state %d", ppl_icd->id, status);
 		switch (status) {
 		case COMP_STATE_INIT:
-			tr_dbg(&ipc_tr, "pipeline %d: reset from init", ppl_icd->id);
+			tr_info(&ipc_tr, "pipeline %d: reset from init", ppl_icd->id);
 			ret = ipc4_pipeline_complete(ipc, ppl_icd->id, cmd);
 			break;
 		case COMP_STATE_READY:
+			tr_info(&ipc_tr, "pipeline %d: reset from ready (no action)", ppl_icd->id);
+			/* No action needed */
+			break;
 		case COMP_STATE_ACTIVE:
+			tr_info(&ipc_tr, "pipeline %d: reset from active (no action)", ppl_icd->id);
+			/* No action needed */
+			break;
 		case COMP_STATE_PAUSED:
+			tr_info(&ipc_tr, "pipeline %d: reset from paused (no action)", ppl_icd->id);
 			/* No action needed */
 			break;
 		default:
 			ipc_cmd_err(&ipc_tr,
-				    "pipeline %d: Invalid state for RESET: %d",
-				    ppl_icd->id, status);
+				    "pipeline %d: Invalid state for RESET: %d (valid: %d,%d,%d,%d)",
+				    ppl_icd->id, status, COMP_STATE_INIT, COMP_STATE_READY,
+				    COMP_STATE_ACTIVE, COMP_STATE_PAUSED);
 			return IPC4_INVALID_REQUEST;
 		}
 

src/ipc/ipc4/logging.c

@@ -121,6 +121,8 @@ int ipc4_logging_enable_logs(bool first_block,
 	const struct log_backend *log_backend = log_backend_adsp_mtrace_get();
 	const struct ipc4_log_state_info *log_state;
 
+	LOG_INF("ipc4_logging_enable_logs: entry first=%d last=%d size=%u", first_block, last_block, data_offset_or_size);
+
 	if (!(first_block && last_block)) {
 		LOG_ERR("log_state data is expected to be sent as one chunk");
 		return -EINVAL;
@@ -139,7 +141,10 @@ int ipc4_logging_enable_logs(bool first_block,
 	 */
 	log_state = (const struct ipc4_log_state_info *)data;
 
+	LOG_INF("ipc4_logging_enable_logs: enable=%d aging_timer=%u", log_state->enable, log_state->aging_timer_period);
+
 	if (log_state->enable) {
+		LOG_INF("ipc4_logging_enable_logs: enabling logs");
 		adsp_mtrace_log_init(mtrace_log_hook);
 
 		k_mutex_init(&log_mutex);
@@ -156,12 +161,16 @@ int ipc4_logging_enable_logs(bool first_block,
 
 		/* Logs enabled, this is the best place to run boot-tests */
 		TEST_RUN_ONCE(sof_run_boot_tests);
+		LOG_INF("ipc4_logging_enable_logs: logs enabled successfully");
 	} else  {
+		LOG_INF("ipc4_logging_enable_logs: disabling logs");
 		k_work_flush_delayable(&log_work, &ipc4_log_work_sync);
 		adsp_mtrace_log_init(NULL);
 		log_backend_disable(log_backend);
+		LOG_INF("ipc4_logging_enable_logs: logs disabled successfully");
 	}
 
+	LOG_INF("ipc4_logging_enable_logs: exit success");
 	return 0;
 }