ipc4: Quiet errors when fuzzing

Fuzzing produces (by design) an endless flood of protocol errors.
Quiet the top level ones when in use, because otherwise the log output
takes up most of the CPU time available that we'd rather spend on
fuzzing.  Same trick from IPC3.

Signed-off-by: Andy Ross <andyross@google.com>

Author: andyross

src/ipc/ipc4/handler.c

@@ -42,6 +42,17 @@
 #include <stddef.h>
 #include <stdint.h>
 
+/* Command format errors during fuzzing are reported for virtually all
+ * commands, and the resulting flood of logging becomes a severe
+ * performance penalty (i.e. we get a lot less fuzzing done per CPU
+ * cycle).
+ */
+#ifdef CONFIG_ARCH_POSIX_LIBFUZZER
+#define ipc_cmd_err(...)
+#else
+#define ipc_cmd_err(...) tr_err(__VA_ARGS__)
+#endif
+
 LOG_MODULE_DECLARE(ipc, CONFIG_SOF_LOG_LEVEL);
 
 struct ipc4_msg_data {
@@ -127,25 +138,25 @@ static int ipc4_pcm_params(struct ipc_comp_dev *pcm_dev)
 
 	/* sanity check comp */
 	if (!pcm_dev->cd->pipeline) {
-		tr_err(&ipc_tr, "ipc: comp %d pipeline not found", pcm_dev->id);
+		ipc_cmd_err(&ipc_tr, "ipc: comp %d pipeline not found", pcm_dev->id);
 		return -EINVAL;
 	}
 
 	/* configure pipeline audio params */
 	err = ipc4_pipeline_params(pcm_dev->cd->pipeline, pcm_dev->cd);
 	if (err < 0) {
-		tr_err(&ipc_tr, "ipc: pipe %d comp %d params failed %d",
-		       pcm_dev->cd->pipeline->pipeline_id,
-		       pcm_dev->cd->pipeline->comp_id, err);
+		ipc_cmd_err(&ipc_tr, "ipc: pipe %d comp %d params failed %d",
+			    pcm_dev->cd->pipeline->pipeline_id,
+			    pcm_dev->cd->pipeline->comp_id, err);
 		goto error;
 	}
 
 	/* prepare pipeline audio params */
 	err = pipeline_prepare(pcm_dev->cd->pipeline, pcm_dev->cd);
 	if (err < 0) {
-		tr_err(&ipc_tr, "ipc: pipe %d comp %d prepare failed %d",
-		       pcm_dev->cd->pipeline->pipeline_id,
-		       pcm_dev->cd->pipeline->comp_id, err);
+		ipc_cmd_err(&ipc_tr, "ipc: pipe %d comp %d prepare failed %d",
+			    pcm_dev->cd->pipeline->pipeline_id,
+			    pcm_dev->cd->pipeline->comp_id, err);
 		goto error;
 	}
 
@@ -154,9 +165,9 @@ static int ipc4_pcm_params(struct ipc_comp_dev *pcm_dev)
 error:
 	reset_err = pipeline_reset(pcm_dev->cd->pipeline, pcm_dev->cd);
 	if (reset_err < 0)
-		tr_err(&ipc_tr, "ipc: pipe %d comp %d reset failed %d",
-		       pcm_dev->cd->pipeline->pipeline_id,
-		       pcm_dev->cd->pipeline->comp_id, reset_err);
+		ipc_cmd_err(&ipc_tr, "ipc: pipe %d comp %d reset failed %d",
+			    pcm_dev->cd->pipeline->pipeline_id,
+			    pcm_dev->cd->pipeline->comp_id, reset_err);
 
 	return err;
 }
@@ -228,7 +239,7 @@ static int set_pipeline_state(struct ipc_comp_dev *ppl_icd, uint32_t cmd,
 
 		host = ipc_get_comp_by_id(ipc, host_id);
 		if (!host) {
-			tr_err(&ipc_tr, "ipc: comp host with ID %d not found", host_id);
+			ipc_cmd_err(&ipc_tr, "ipc: comp host with ID %d not found", host_id);
 			return IPC4_INVALID_RESOURCE_ID;
 		}
 	}
@@ -251,7 +262,7 @@ static int set_pipeline_state(struct ipc_comp_dev *ppl_icd, uint32_t cmd,
 			cmd = COMP_TRIGGER_PRE_RELEASE;
 			break;
 		default:
-			tr_err(&ipc_tr, "ipc: current status %d", status);
+			ipc_cmd_err(&ipc_tr, "ipc: current status %d", status);
 			return IPC4_INVALID_REQUEST;
 		}
 		break;
@@ -270,15 +281,15 @@ static int set_pipeline_state(struct ipc_comp_dev *ppl_icd, uint32_t cmd,
 		case COMP_STATE_PAUSED:
 			ret = pipeline_trigger(host->cd->pipeline, host->cd, COMP_TRIGGER_STOP);
 			if (ret < 0) {
-				tr_err(&ipc_tr, "ipc: comp %d trigger 0x%x failed %d",
-						ppl_icd->id, cmd, ret);
+				ipc_cmd_err(&ipc_tr, "ipc: comp %d trigger 0x%x failed %d",
+					    ppl_icd->id, cmd, ret);
 				return IPC4_PIPELINE_STATE_NOT_SET;
 			}
 			if (ret == PPL_STATUS_SCHEDULED)
 				*delayed = true;
 			break;
 		default:
-			tr_err(&ipc_tr, "ipc: invalid status %d for RESET", status);
+			ipc_cmd_err(&ipc_tr, "ipc: invalid status %d for RESET", status);
 			return IPC4_INVALID_REQUEST;
 		}
 
@@ -317,14 +328,14 @@ static int set_pipeline_state(struct ipc_comp_dev *ppl_icd, uint32_t cmd,
 	case SOF_IPC4_PIPELINE_STATE_SAVED:
 	case SOF_IPC4_PIPELINE_STATE_ERROR_STOP:
 	default:
-		tr_err(&ipc_tr, "ipc: unsupported trigger cmd 0x%x", cmd);
+		ipc_cmd_err(&ipc_tr, "ipc: unsupported trigger cmd 0x%x", cmd);
 		return IPC4_INVALID_REQUEST;
 	}
 
 	/* trigger the component */
 	ret = pipeline_trigger(host->cd->pipeline, host->cd, cmd);
 	if (ret < 0) {
-		tr_err(&ipc_tr, "ipc: comp %d trigger 0x%x failed %d", ppl_icd->id, cmd, ret);
+		ipc_cmd_err(&ipc_tr, "ipc: comp %d trigger 0x%x failed %d", ppl_icd->id, cmd, ret);
 		ret = IPC4_PIPELINE_STATE_NOT_SET;
 	} else if (ret == PPL_STATUS_SCHEDULED) {
 		*delayed = true;
@@ -345,7 +356,7 @@ static void ipc_compound_pre_start(int msg_id)
 static void ipc_compound_post_start(uint32_t msg_id, int ret, bool delayed)
 {
 	if (ret) {
-		tr_err(&ipc_tr, "failed to process msg %d status %d", msg_id, ret);
+		ipc_cmd_err(&ipc_tr, "failed to process msg %d status %d", msg_id, ret);
 		atomic_set(&msg_data.delayed_reply, 0);
 		return;
 	}
@@ -358,7 +369,7 @@ static void ipc_compound_post_start(uint32_t msg_id, int ret, bool delayed)
 static void ipc_compound_msg_done(uint32_t msg_id, int error)
 {
 	if (!atomic_read(&msg_data.delayed_reply)) {
-		tr_err(&ipc_tr, "unexpected delayed reply");
+		ipc_cmd_err(&ipc_tr, "unexpected delayed reply");
 		return;
 	}
 
@@ -379,7 +390,7 @@ static int ipc_wait_for_compound_msg(void)
 		k_sleep(Z_TIMEOUT_US(250));
 
 		if (!try_count--) {
-			tr_err(&ipc_tr, "failed to wait schedule thread");
+			ipc_cmd_err(&ipc_tr, "failed to wait schedule thread");
 			return IPC4_FAILURE;
 		}
 	}
@@ -421,7 +432,7 @@ static int ipc4_set_pipeline_state(struct ipc4_message_request *ipc4)
 
 		ppl_icd = ipc_get_comp_by_ppl_id(ipc, COMP_TYPE_PIPELINE, ppl_id[i]);
 		if (!ppl_icd) {
-			tr_err(&ipc_tr, "ipc: comp %d not found", ppl_id[i]);
+			ipc_cmd_err(&ipc_tr, "ipc: comp %d not found", ppl_id[i]);
 			return IPC4_INVALID_RESOURCE_ID;
 		}
 
@@ -536,16 +547,16 @@ static int ipc4_process_ipcgtw_cmd(struct ipc4_message_request *ipc4)
 		if (msg_reply.tx_data) {
 			msg_reply.tx_size = reply_size;
 		} else {
-			tr_err(&ipc_tr, "failed to allocate %u bytes for msg_reply.tx_data",
-			       reply_size);
+			ipc_cmd_err(&ipc_tr, "failed to allocate %u bytes for msg_reply.tx_data",
+				    reply_size);
 			msg_reply.extension = 0;
 			return IPC4_OUT_OF_MEMORY;
 		}
 	}
 
 	return err < 0 ? IPC4_FAILURE : IPC4_SUCCESS;
 #else
-	tr_err(&ipc_tr, "CONFIG_IPC4_GATEWAY is disabled");
+	ipc_cmd_err(&ipc_tr, "CONFIG_IPC4_GATEWAY is disabled");
 	return IPC4_UNAVAILABLE;
 #endif
 }
@@ -563,7 +574,7 @@ static int ipc4_process_glb_message(struct ipc4_message_request *ipc4)
 	case SOF_IPC4_GLB_PERF_MEASUREMENTS_CMD:
 	case SOF_IPC4_GLB_LOAD_MULTIPLE_MODULES:
 	case SOF_IPC4_GLB_UNLOAD_MULTIPLE_MODULES:
-		tr_err(&ipc_tr, "not implemented ipc message type %d", type);
+		ipc_cmd_err(&ipc_tr, "not implemented ipc message type %d", type);
 		ret = IPC4_UNAVAILABLE;
 		break;
 
@@ -586,7 +597,7 @@ static int ipc4_process_glb_message(struct ipc4_message_request *ipc4)
 	case SOF_IPC4_GLB_GET_PIPELINE_CONTEXT_SIZE:
 	case SOF_IPC4_GLB_SAVE_PIPELINE:
 	case SOF_IPC4_GLB_RESTORE_PIPELINE:
-		tr_err(&ipc_tr, "not implemented ipc message type %d", type);
+		ipc_cmd_err(&ipc_tr, "not implemented ipc message type %d", type);
 		ret = IPC4_UNAVAILABLE;
 		break;
 
@@ -597,13 +608,13 @@ static int ipc4_process_glb_message(struct ipc4_message_request *ipc4)
 		break;
 #endif
 	case SOF_IPC4_GLB_INTERNAL_MESSAGE:
-		tr_err(&ipc_tr, "not implemented ipc message type %d", type);
+		ipc_cmd_err(&ipc_tr, "not implemented ipc message type %d", type);
 		ret = IPC4_UNAVAILABLE;
 		break;
 
 	/* Notification (FW to SW driver) */
 	case SOF_IPC4_GLB_NOTIFICATION:
-		tr_err(&ipc_tr, "not implemented ipc message type %d", type);
+		ipc_cmd_err(&ipc_tr, "not implemented ipc message type %d", type);
 		ret = IPC4_UNAVAILABLE;
 		break;
 
@@ -612,7 +623,7 @@ static int ipc4_process_glb_message(struct ipc4_message_request *ipc4)
 		break;
 
 	default:
-		tr_err(&ipc_tr, "unsupported ipc message type %d", type);
+		ipc_cmd_err(&ipc_tr, "unsupported ipc message type %d", type);
 		ret = IPC4_UNAVAILABLE;
 		break;
 	}
@@ -649,9 +660,9 @@ static int ipc4_init_module_instance(struct ipc4_message_request *ipc4)
 
 	dev = comp_new_ipc4(&module_init);
 	if (!dev) {
-		tr_err(&ipc_tr, "error: failed to init module %x : %x",
-		       (uint32_t)module_init.primary.r.module_id,
-		       (uint32_t)module_init.primary.r.instance_id);
+		ipc_cmd_err(&ipc_tr, "error: failed to init module %x : %x",
+			    (uint32_t)module_init.primary.r.module_id,
+			    (uint32_t)module_init.primary.r.instance_id);
 		return IPC4_MOD_NOT_INITIALIZED;
 	}
 
@@ -762,7 +773,7 @@ static int ipc4_get_large_config_module_instance(struct ipc4_message_request *ip
 		msg_reply.tx_size = data_offset;
 		msg_reply.tx_data = response_buffer;
 	} else {
-		tr_err(&ipc_tr, "error: failed to allocate tx_data");
+		ipc_cmd_err(&ipc_tr, "error: failed to allocate tx_data");
 		ret = IPC4_OUT_OF_MEMORY;
 	}
 
@@ -810,9 +821,9 @@ static int ipc4_set_large_config_module_instance(struct ipc4_message_request *ip
 					config.extension.r.data_off_size,
 					(const char *)MAILBOX_HOSTBOX_BASE);
 	if (ret < 0) {
-		tr_err(&ipc_tr, "failed to set large_config_module_instance %x : %x",
-		       (uint32_t)config.primary.r.module_id,
-		       (uint32_t)config.primary.r.instance_id);
+		ipc_cmd_err(&ipc_tr, "failed to set large_config_module_instance %x : %x",
+			    (uint32_t)config.primary.r.module_id,
+			    (uint32_t)config.primary.r.instance_id);
 		ret = IPC4_INVALID_RESOURCE_ID;
 	}
 
@@ -835,9 +846,9 @@ static int ipc4_delete_module_instance(struct ipc4_message_request *ipc4)
 	comp_id = IPC4_COMP_ID(module.primary.r.module_id, module.primary.r.instance_id);
 	ret = ipc_comp_free(ipc, comp_id);
 	if (ret < 0) {
-		tr_err(&ipc_tr, "failed to delete module instance %x : %x",
-		       (uint32_t)module.primary.r.module_id,
-		       (uint32_t)module.primary.r.instance_id);
+		ipc_cmd_err(&ipc_tr, "failed to delete module instance %x : %x",
+			    (uint32_t)module.primary.r.module_id,
+			    (uint32_t)module.primary.r.instance_id);
 		ret = IPC4_INVALID_RESOURCE_ID;
 	}
 
@@ -861,7 +872,7 @@ static int ipc4_module_process_d0ix(struct ipc4_message_request *ipc4)
 
 	/* only module 0 can be used to set d0ix state */
 	if (d0ix.primary.r.module_id || d0ix.primary.r.instance_id) {
-		tr_err(&ipc_tr, "invalid resource id %x : %x", module_id, instance_id);
+		ipc_cmd_err(&ipc_tr, "invalid resource id %x : %x", module_id, instance_id);
 		return IPC4_INVALID_RESOURCE_ID;
 	}
 
@@ -890,7 +901,7 @@ static int ipc4_module_process_dx(struct ipc4_message_request *ipc4)
 
 	/* only module 0 can be used to set dx state */
 	if (module_id || instance_id) {
-		tr_err(&ipc_tr, "invalid resource id %x : %x", module_id, instance_id);
+		ipc_cmd_err(&ipc_tr, "invalid resource id %x : %x", module_id, instance_id);
 		return IPC4_INVALID_RESOURCE_ID;
 	}
 
@@ -903,16 +914,16 @@ static int ipc4_module_process_dx(struct ipc4_message_request *ipc4)
 
 	/* check if core enable mask is valid */
 	if (dx_info.core_mask > MASK(CONFIG_CORE_COUNT - 1, 0)) {
-		tr_err(&ipc_tr, "ipc4_module_process_dx: CONFIG_CORE_COUNT: %d < core enable mask: %d",
-		       CONFIG_CORE_COUNT, dx_info.core_mask);
+		ipc_cmd_err(&ipc_tr, "ipc4_module_process_dx: CONFIG_CORE_COUNT: %d < core enable mask: %d",
+			    CONFIG_CORE_COUNT, dx_info.core_mask);
 		return IPC4_ERROR_INVALID_PARAM;
 	}
 
 	/* check primary core first */
 	if ((dx_info.core_mask & BIT(PLATFORM_PRIMARY_CORE_ID)) &&
 	    (dx_info.dx_mask & BIT(PLATFORM_PRIMARY_CORE_ID))) {
 		/* core0 can't be activated more, it's already active since we got here */
-		tr_err(&ipc_tr, "Core0 is already active");
+		ipc_cmd_err(&ipc_tr, "Core0 is already active");
 		return IPC4_BAD_STATE;
 	}
 
@@ -924,13 +935,13 @@ static int ipc4_module_process_dx(struct ipc4_message_request *ipc4)
 		if (dx_info.dx_mask & BIT(core_id)) {
 			ret = cpu_enable_core(core_id);
 			if (ret != 0) {
-				tr_err(&ipc_tr, "failed to enable core %d", core_id);
+				ipc_cmd_err(&ipc_tr, "failed to enable core %d", core_id);
 				return IPC4_FAILURE;
 			}
 		} else {
 			cpu_disable_core(core_id);
 			if (cpu_is_core_enabled(core_id)) {
-				tr_err(&ipc_tr, "failed to disable core %d", core_id);
+				ipc_cmd_err(&ipc_tr, "failed to disable core %d", core_id);
 				return IPC4_FAILURE;
 			}
 		}
@@ -939,13 +950,13 @@ static int ipc4_module_process_dx(struct ipc4_message_request *ipc4)
 	/* Deactivating primary core if requested.  */
 	if (dx_info.core_mask & BIT(PLATFORM_PRIMARY_CORE_ID)) {
 		if (cpu_enabled_cores() & ~BIT(PLATFORM_PRIMARY_CORE_ID)) {
-			tr_err(&ipc_tr, "secondary cores 0x%x still active",
-			       cpu_enabled_cores());
+			ipc_cmd_err(&ipc_tr, "secondary cores 0x%x still active",
+				    cpu_enabled_cores());
 			return IPC4_BUSY;
 		}
 
 		if (is_any_ppl_active()) {
-			tr_err(&ipc_tr, "some pipelines are still active");
+			ipc_cmd_err(&ipc_tr, "some pipelines are still active");
 			return IPC4_BUSY;
 		}
 
@@ -1130,16 +1141,16 @@ void ipc_cmd(struct ipc_cmd_hdr *_hdr)
 	case SOF_IPC4_MESSAGE_TARGET_FW_GEN_MSG:
 		err = ipc4_process_glb_message(in);
 		if (err)
-			tr_err(&ipc_tr, "ipc4: FW_GEN_MSG failed with err %d", err);
+			ipc_cmd_err(&ipc_tr, "ipc4: FW_GEN_MSG failed with err %d", err);
 		break;
 	case SOF_IPC4_MESSAGE_TARGET_MODULE_MSG:
 		err = ipc4_process_module_message(in);
 		if (err)
-			tr_err(&ipc_tr, "ipc4: MODULE_MSG failed with err %d", err);
+			ipc_cmd_err(&ipc_tr, "ipc4: MODULE_MSG failed with err %d", err);
 		break;
 	default:
 		/* should not reach here as we only have 2 message types */
-		tr_err(&ipc_tr, "ipc4: invalid target %d", target);
+		ipc_cmd_err(&ipc_tr, "ipc4: invalid target %d", target);
 		err = IPC4_UNKNOWN_MESSAGE_TYPE;
 	}
 
@@ -1161,7 +1172,7 @@ void ipc_cmd(struct ipc_cmd_hdr *_hdr)
 			return;
 
 		if (ipc_wait_for_compound_msg() != 0) {
-			tr_err(&ipc_tr, "ipc4: failed to send delayed reply");
+			ipc_cmd_err(&ipc_tr, "ipc4: failed to send delayed reply");
 			err = IPC4_FAILURE;
 		}