[RFC PATCH 0/4] Drop custom logging

[RFC PATCH 0/4] Drop custom logging

[Umang Jain]

Drop custom logging from the vchiq interface.
Mostly of them are replaced with dev_dbg and friends
and/or pr_info and friends. 

The debugfs log levels (in 4/4) are mapped to kernel
logs levels (coming from include/linux/kern_levels.h)
Would like some thoughts on it as I am not sure (hence
marking this is RFC)

From drivers/staging/vc04_services/interface/TODO:

"""
* Cleanup logging mechanism

The driver should probably be using the standard kernel logging mechanisms
such as dev_info, dev_dbg, and friends.
"""

Umang Jain (4):
  staging: vc04_services: vchiq_core: Drop custom logging
  staging: vc04_services: vchiq_arm: Drop custom logging
  staging: vc04_services: Drop custom logging
  staging: vc04_services: Drop remnants of custom logging

 .../interface/vchiq_arm/vchiq_arm.c           | 151 +++---
 .../interface/vchiq_arm/vchiq_connected.c     |   5 +-
 .../interface/vchiq_arm/vchiq_core.c          | 479 ++++++++----------
 .../interface/vchiq_arm/vchiq_core.h          |  39 --
 .../interface/vchiq_arm/vchiq_debugfs.c       |  26 +-
 .../interface/vchiq_arm/vchiq_dev.c           |  78 ++-
 6 files changed, 329 insertions(+), 449 deletions(-)

-- 
2.39.0

[RFC PATCH 1/4] staging: vc04_services: vchiq_core: Drop custom logging

[Umang Jain]

Drop custom logging from the vchiq_core.c and use standard kernel
logging infrastructure (dev_dbg() and friends for struct Device
stuff) and pr_info (and similar) for vchiq_services/instances things.

Signed-off-by: Umang Jain <umang.jain@ideasonboard.com>
---
 .../interface/vchiq_arm/vchiq_core.c          | 450 ++++++++----------
 1 file changed, 204 insertions(+), 246 deletions(-)

diff --git a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
index 4e705a447a62..7b3c57326d28 100644
--- a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
+++ b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
@@ -227,10 +227,11 @@ static const char *msg_type_str(unsigned int msg_type)
 static inline void
 set_service_state(struct vchiq_service *service, int newstate)
 {
-	vchiq_log_info(vchiq_core_log_level, "%d: srv:%d %s->%s",
-		       service->state->id, service->localport,
-		       srvstate_names[service->srvstate],
-		       srvstate_names[newstate]);
+	struct vchiq_state *state = service->state;
+
+	dev_info(state->dev, "%d: srv:%d %s->%s", state->id,
+		 service->localport, srvstate_names[service->srvstate],
+		 srvstate_names[newstate]);
 	service->srvstate = newstate;
 }
 
@@ -255,8 +256,7 @@ find_service_by_handle(struct vchiq_instance *instance, unsigned int handle)
 		return service;
 	}
 	rcu_read_unlock();
-	vchiq_log_info(vchiq_core_log_level,
-		       "Invalid service handle 0x%x", handle);
+	pr_info("vchiq: Invalid service handle 0x%x", handle);
 	return NULL;
 }
 
@@ -276,8 +276,7 @@ find_service_by_port(struct vchiq_state *state, unsigned int localport)
 		}
 		rcu_read_unlock();
 	}
-	vchiq_log_info(vchiq_core_log_level,
-		       "Invalid port %u", localport);
+	dev_info(state->dev, "Invalid port %u", localport);
 	return NULL;
 }
 
@@ -297,8 +296,7 @@ find_service_for_instance(struct vchiq_instance *instance, unsigned int handle)
 		return service;
 	}
 	rcu_read_unlock();
-	vchiq_log_info(vchiq_core_log_level,
-		       "Invalid service handle 0x%x", handle);
+	pr_info("vchiq: Invalid service handle 0x%x", handle);
 	return NULL;
 }
 
@@ -320,8 +318,7 @@ find_closed_service_for_instance(struct vchiq_instance *instance, unsigned int h
 		return service;
 	}
 	rcu_read_unlock();
-	vchiq_log_info(vchiq_core_log_level,
-		       "Invalid service handle 0x%x", handle);
+	pr_info("vchiq: Invalid service handle 0x%x", handle);
 	return service;
 }
 
@@ -469,15 +466,15 @@ make_service_callback(struct vchiq_service *service, enum vchiq_reason reason,
 {
 	int status;
 
-	vchiq_log_trace(vchiq_core_log_level, "%d: callback:%d (%s, %pK, %pK)",
-			service->state->id, service->localport, reason_names[reason],
-			header, bulk_userdata);
+	dev_dbg(service->state->dev, "%d: callback:%d (%s, %pK, %pK)",
+		service->state->id, service->localport, reason_names[reason],
+		header, bulk_userdata);
 	status = service->base.callback(service->instance, reason, header, service->handle,
 					bulk_userdata);
 	if (status && (status != -EAGAIN)) {
-		vchiq_log_warning(vchiq_core_log_level,
-				  "%d: ignoring ERROR from callback to service %x",
-				  service->state->id, service->handle);
+		dev_warn(service->state->dev,
+			 "%d: ignoring ERROR from callback to service %x",
+			 service->state->id, service->handle);
 		status = 0;
 	}
 
@@ -492,8 +489,8 @@ vchiq_set_conn_state(struct vchiq_state *state, enum vchiq_connstate newstate)
 {
 	enum vchiq_connstate oldstate = state->conn_state;
 
-	vchiq_log_info(vchiq_core_log_level, "%d: %s->%s", state->id, conn_state_names[oldstate],
-		       conn_state_names[newstate]);
+	dev_info(state->dev, "%d: %s->%s", state->id, conn_state_names[oldstate],
+		 conn_state_names[newstate]);
 	state->conn_state = newstate;
 	vchiq_platform_conn_state_changed(state, oldstate, newstate);
 }
@@ -741,10 +738,9 @@ process_free_data_message(struct vchiq_state *state, u32 *service_found,
 		 */
 		complete(&quota->quota_event);
 	} else if (count == 0) {
-		vchiq_log_error(vchiq_core_log_level,
-				"service %d message_use_count=%d (header %pK, msgid %x, header->msgid %x, header->size %x)",
-				port, quota->message_use_count, header, msgid, header->msgid,
-				header->size);
+		dev_err(state->dev,
+			"service %d message_use_count=%d (header %pK, msgid %x, header->msgid %x, header->size %x)",
+			port, quota->message_use_count, header, msgid, header->msgid, header->size);
 		WARN(1, "invalid message use count\n");
 	}
 	if (!BITSET_IS_SET(service_found, port)) {
@@ -763,12 +759,12 @@ process_free_data_message(struct vchiq_state *state, u32 *service_found,
 			 * it has dropped below its quota
 			 */
 			complete(&quota->quota_event);
-			vchiq_log_trace(vchiq_core_log_level, "%d: pfq:%d %x@%pK - slot_use->%d",
-					state->id, port, header->size, header, count - 1);
+			dev_dbg(state->dev, "%d: pfq:%d %x@%pK - slot_use->%d",
+				state->id, port, header->size, header, count - 1);
 		} else {
-			vchiq_log_error(vchiq_core_log_level,
-					"service %d slot_use_count=%d (header %pK, msgid %x, header->msgid %x, header->size %x)",
-					port, count, header, msgid, header->msgid, header->size);
+			dev_dbg(state->dev,
+				"service %d slot_use_count=%d (header %pK, msgid %x, header->msgid %x, header->size %x)",
+				port, count, header, msgid, header->msgid, header->size);
 			WARN(1, "bad slot use count\n");
 		}
 	}
@@ -809,9 +805,8 @@ process_free_queue(struct vchiq_state *state, u32 *service_found,
 		 */
 		rmb();
 
-		vchiq_log_trace(vchiq_core_log_level, "%d: pfq %d=%pK %x %x",
-				state->id, slot_index, data, local->slot_queue_recycle,
-				slot_queue_available);
+		dev_dbg(state->dev, "%d: pfq %d=%pK %x %x", state->id, slot_index,
+			data, local->slot_queue_recycle, slot_queue_available);
 
 		/* Initialise the bitmask for services which have used this slot */
 		memset(service_found, 0, length);
@@ -831,9 +826,9 @@ process_free_queue(struct vchiq_state *state, u32 *service_found,
 
 			pos += calc_stride(header->size);
 			if (pos > VCHIQ_SLOT_SIZE) {
-				vchiq_log_error(vchiq_core_log_level,
-						"pfq - pos %x: header %pK, msgid %x, header->msgid %x, header->size %x",
-						pos, header, msgid, header->msgid, header->size);
+				dev_err(state->dev,
+					"pfq - pos %x: header %pK, msgid %x, header->msgid %x, header->size %x",
+					pos, header, msgid, header->msgid, header->size);
 				WARN(1, "invalid slot position\n");
 			}
 		}
@@ -980,10 +975,10 @@ queue_message(struct vchiq_state *state, struct vchiq_service *service,
 		       ((tx_end_index != quota->previous_tx_index) &&
 			(quota->slot_use_count == quota->slot_quota))) {
 			spin_unlock(&quota_spinlock);
-			vchiq_log_trace(vchiq_core_log_level,
-					"%d: qm:%d %s,%zx - quota stall (msg %d, slot %d)",
-					state->id, service->localport, msg_type_str(type), size,
-					quota->message_use_count, quota->slot_use_count);
+			dev_dbg(state->dev,
+				"%d: qm:%d %s,%zx - quota stall (msg %d, slot %d)",
+				state->id, service->localport, msg_type_str(type), size,
+				quota->message_use_count, quota->slot_use_count);
 			VCHIQ_SERVICE_STATS_INC(service, quota_stalls);
 			mutex_unlock(&state->slot_mutex);
 			if (wait_for_completion_interruptible(&quota->quota_event))
@@ -1023,9 +1018,9 @@ queue_message(struct vchiq_state *state, struct vchiq_service *service,
 		int tx_end_index;
 		int slot_use_count;
 
-		vchiq_log_info(vchiq_core_log_level, "%d: qm %s@%pK,%zx (%d->%d)", state->id,
-			       msg_type_str(VCHIQ_MSG_TYPE(msgid)), header, size,
-			       VCHIQ_MSG_SRCPORT(msgid), VCHIQ_MSG_DSTPORT(msgid));
+		dev_info(state->dev, "%d: qm %s@%pK,%zx (%d->%d)", state->id,
+			 msg_type_str(VCHIQ_MSG_TYPE(msgid)), header, size,
+			 VCHIQ_MSG_SRCPORT(msgid), VCHIQ_MSG_DSTPORT(msgid));
 
 		WARN_ON(flags & (QMFLAGS_NO_MUTEX_LOCK |
 				 QMFLAGS_NO_MUTEX_UNLOCK));
@@ -1075,17 +1070,17 @@ queue_message(struct vchiq_state *state, struct vchiq_service *service,
 		spin_unlock(&quota_spinlock);
 
 		if (slot_use_count)
-			vchiq_log_trace(vchiq_core_log_level,
-					"%d: qm:%d %s,%zx - slot_use->%d (hdr %p)", state->id,
-					service->localport, msg_type_str(VCHIQ_MSG_TYPE(msgid)),
-					size, slot_use_count, header);
+			dev_dbg(state->dev,
+				"%d: qm:%d %s,%zx - slot_use->%d (hdr %p)", state->id,
+				service->localport, msg_type_str(VCHIQ_MSG_TYPE(msgid)),
+				size, slot_use_count, header);
 
 		VCHIQ_SERVICE_STATS_INC(service, ctrl_tx_count);
 		VCHIQ_SERVICE_STATS_ADD(service, ctrl_tx_bytes, size);
 	} else {
-		vchiq_log_info(vchiq_core_log_level, "%d: qm %s@%pK,%zx (%d->%d)", state->id,
-			       msg_type_str(VCHIQ_MSG_TYPE(msgid)), header, size,
-			       VCHIQ_MSG_SRCPORT(msgid), VCHIQ_MSG_DSTPORT(msgid));
+		dev_dbg(state->dev, "%d: qm %s@%pK,%zx (%d->%d)", state->id,
+			msg_type_str(VCHIQ_MSG_TYPE(msgid)), header, size,
+			VCHIQ_MSG_SRCPORT(msgid), VCHIQ_MSG_DSTPORT(msgid));
 		if (size != 0) {
 			/*
 			 * It is assumed for now that this code path
@@ -1113,11 +1108,11 @@ queue_message(struct vchiq_state *state, struct vchiq_service *service,
 			? service->base.fourcc
 			: VCHIQ_MAKE_FOURCC('?', '?', '?', '?');
 
-		vchiq_log_info(SRVTRACE_LEVEL(service),
-			       "Sent Msg %s(%u) to %c%c%c%c s:%u d:%d len:%zu",
-			       msg_type_str(VCHIQ_MSG_TYPE(msgid)), VCHIQ_MSG_TYPE(msgid),
-			       VCHIQ_FOURCC_AS_4CHARS(svc_fourcc), VCHIQ_MSG_SRCPORT(msgid),
-			       VCHIQ_MSG_DSTPORT(msgid), size);
+		dev_info(state->dev,
+			 "Sent Msg %s(%u) to %c%c%c%c s:%u d:%d len:%zu",
+			 msg_type_str(VCHIQ_MSG_TYPE(msgid)), VCHIQ_MSG_TYPE(msgid),
+			 VCHIQ_FOURCC_AS_4CHARS(svc_fourcc), VCHIQ_MSG_SRCPORT(msgid),
+			 VCHIQ_MSG_DSTPORT(msgid), size);
 	}
 
 	/* Make sure the new header is visible to the peer. */
@@ -1168,15 +1163,15 @@ queue_message_sync(struct vchiq_state *state, struct vchiq_service *service,
 		int oldmsgid = header->msgid;
 
 		if (oldmsgid != VCHIQ_MSGID_PADDING)
-			vchiq_log_error(vchiq_core_log_level, "%d: qms - msgid %x, not PADDING",
-					state->id, oldmsgid);
+			dev_err(state->dev, "%d: qms - msgid %x, not PADDING",
+				state->id, oldmsgid);
 	}
 
-	vchiq_log_info(vchiq_sync_log_level,
-		       "%d: qms %s@%pK,%x (%d->%d)", state->id,
-		       msg_type_str(VCHIQ_MSG_TYPE(msgid)),
-		       header, size, VCHIQ_MSG_SRCPORT(msgid),
-		       VCHIQ_MSG_DSTPORT(msgid));
+	dev_info(state->dev,
+		 "%d: qms %s@%pK,%x (%d->%d)", state->id,
+		 msg_type_str(VCHIQ_MSG_TYPE(msgid)),
+		 header, size, VCHIQ_MSG_SRCPORT(msgid),
+		 VCHIQ_MSG_DSTPORT(msgid));
 
 	callback_result =
 		copy_message_data(copy_callback, context,
@@ -1211,11 +1206,11 @@ queue_message_sync(struct vchiq_state *state, struct vchiq_service *service,
 			? service->base.fourcc
 			: VCHIQ_MAKE_FOURCC('?', '?', '?', '?');
 
-		vchiq_log_trace(vchiq_sync_log_level,
-				"Sent Sync Msg %s(%u) to %c%c%c%c s:%u d:%d len:%d",
-				msg_type_str(VCHIQ_MSG_TYPE(msgid)), VCHIQ_MSG_TYPE(msgid),
-				VCHIQ_FOURCC_AS_4CHARS(svc_fourcc), VCHIQ_MSG_SRCPORT(msgid),
-				VCHIQ_MSG_DSTPORT(msgid), size);
+		dev_dbg(state->dev,
+			"Sent Sync Msg %s(%u) to %c%c%c%c s:%u d:%d len:%d",
+			msg_type_str(VCHIQ_MSG_TYPE(msgid)), VCHIQ_MSG_TYPE(msgid),
+			VCHIQ_FOURCC_AS_4CHARS(svc_fourcc), VCHIQ_MSG_SRCPORT(msgid),
+			VCHIQ_MSG_DSTPORT(msgid), size);
 	}
 
 	remote_event_signal(&state->remote->sync_trigger);
@@ -1268,9 +1263,9 @@ release_slot(struct vchiq_state *state, struct vchiq_slot_info *slot_info,
 			VCHIQ_SLOT_QUEUE_MASK] =
 			SLOT_INDEX_FROM_INFO(state, slot_info);
 		state->remote->slot_queue_recycle = slot_queue_recycle + 1;
-		vchiq_log_info(vchiq_core_log_level, "%d: %s %d - recycle->%x", state->id, __func__,
-			       SLOT_INDEX_FROM_INFO(state, slot_info),
-			       state->remote->slot_queue_recycle);
+		dev_info(state->dev, "%d: %s %d - recycle->%x", state->id, __func__,
+			 SLOT_INDEX_FROM_INFO(state, slot_info),
+			 state->remote->slot_queue_recycle);
 
 		/*
 		 * A write barrier is necessary, but remote_event_signal
@@ -1305,9 +1300,9 @@ notify_bulks(struct vchiq_service *service, struct vchiq_bulk_queue *queue,
 {
 	int status = 0;
 
-	vchiq_log_trace(vchiq_core_log_level, "%d: nb:%d %cx - p=%x rn=%x r=%x", service->state->id,
-			service->localport, (queue == &service->bulk_tx) ? 't' : 'r',
-			queue->process, queue->remote_notify, queue->remove);
+	dev_dbg(service->state->dev, "%d: nb:%d %cx - p=%x rn=%x r=%x", service->state->id,
+		service->localport, (queue == &service->bulk_tx) ? 't' : 'r',
+		queue->process, queue->remote_notify, queue->remove);
 
 	queue->remote_notify = queue->process;
 
@@ -1387,9 +1382,8 @@ poll_services_of_group(struct vchiq_state *state, int group)
 
 		service_flags = atomic_xchg(&service->poll_flags, 0);
 		if (service_flags & BIT(VCHIQ_POLL_REMOVE)) {
-			vchiq_log_info(vchiq_core_log_level, "%d: ps - remove %d<->%d",
-				       state->id, service->localport,
-				       service->remoteport);
+			dev_info(state->dev, "%d: ps - remove %d<->%d",
+				 state->id, service->localport, service->remoteport);
 
 			/*
 			 * Make it look like a client, because
@@ -1401,8 +1395,8 @@ poll_services_of_group(struct vchiq_state *state, int group)
 			if (vchiq_close_service_internal(service, NO_CLOSE_RECVD))
 				request_poll(state, service, VCHIQ_POLL_REMOVE);
 		} else if (service_flags & BIT(VCHIQ_POLL_TERMINATE)) {
-			vchiq_log_info(vchiq_core_log_level, "%d: ps - terminate %d<->%d",
-				       state->id, service->localport, service->remoteport);
+			dev_dbg(state->dev, "%d: ps - terminate %d<->%d",
+				state->id, service->localport, service->remoteport);
 			if (vchiq_close_service_internal(service, NO_CLOSE_RECVD))
 				request_poll(state, service, VCHIQ_POLL_TERMINATE);
 		}
@@ -1431,9 +1425,9 @@ abort_outstanding_bulks(struct vchiq_service *service,
 {
 	int is_tx = (queue == &service->bulk_tx);
 
-	vchiq_log_trace(vchiq_core_log_level, "%d: aob:%d %cx - li=%x ri=%x p=%x",
-			service->state->id, service->localport, is_tx ? 't' : 'r',
-			queue->local_insert, queue->remote_insert, queue->process);
+	dev_dbg(service->state->dev, "%d: aob:%d %cx - li=%x ri=%x p=%x",
+		service->state->id, service->localport, is_tx ? 't' : 'r',
+		queue->local_insert, queue->remote_insert, queue->process);
 
 	WARN_ON((int)(queue->local_insert - queue->process) < 0);
 	WARN_ON((int)(queue->remote_insert - queue->process) < 0);
@@ -1452,11 +1446,11 @@ abort_outstanding_bulks(struct vchiq_service *service,
 		if (queue->process != queue->local_insert) {
 			vchiq_complete_bulk(service->instance, bulk);
 
-			vchiq_log_info(SRVTRACE_LEVEL(service),
-				       "%s %c%c%c%c d:%d ABORTED - tx len:%d, rx len:%d",
-				       is_tx ? "Send Bulk to" : "Recv Bulk from",
-				       VCHIQ_FOURCC_AS_4CHARS(service->base.fourcc),
-				       service->remoteport, bulk->size, bulk->remote_size);
+			dev_dbg(service->state->dev,
+				"%s %c%c%c%c d:%d ABORTED - tx len:%d, rx len:%d",
+				is_tx ? "Send Bulk to" : "Recv Bulk from",
+				VCHIQ_FOURCC_AS_4CHARS(service->base.fourcc),
+				service->remoteport, bulk->size, bulk->remote_size);
 		} else {
 			/* fabricate a matching dummy bulk */
 			bulk->data = 0;
@@ -1489,8 +1483,8 @@ parse_open(struct vchiq_state *state, struct vchiq_header *header)
 
 	payload = (struct vchiq_open_payload *)header->data;
 	fourcc = payload->fourcc;
-	vchiq_log_info(vchiq_core_log_level, "%d: prs OPEN@%pK (%d->'%c%c%c%c')",
-		       state->id, header, localport, VCHIQ_FOURCC_AS_4CHARS(fourcc));
+	dev_info(state->dev, "%d: prs OPEN@%pK (%d->'%c%c%c%c')",
+		 state->id, header, localport, VCHIQ_FOURCC_AS_4CHARS(fourcc));
 
 	service = get_listening_service(state, fourcc);
 	if (!service)
@@ -1502,11 +1496,9 @@ parse_open(struct vchiq_state *state, struct vchiq_header *header)
 
 	if ((service->version < version_min) || (version < service->version_min)) {
 		/* Version mismatch */
-		vchiq_loud_error_header();
-		vchiq_loud_error("%d: service %d (%c%c%c%c) version mismatch - local (%d, min %d) vs. remote (%d, min %d)",
-				 state->id, service->localport, VCHIQ_FOURCC_AS_4CHARS(fourcc),
-				 service->version, service->version_min, version, version_min);
-		vchiq_loud_error_footer();
+		pr_err("%d: service %d (%c%c%c%c) version mismatch - local (%d, min %d) vs. remote (%d, min %d)",
+		       state->id, service->localport, VCHIQ_FOURCC_AS_4CHARS(fourcc),
+		       service->version, service->version_min, version, version_min);
 		vchiq_service_put(service);
 		service = NULL;
 		goto fail_open;
@@ -1614,17 +1606,17 @@ parse_message(struct vchiq_state *state, struct vchiq_header *header)
 				vchiq_service_put(service);
 			service = get_connected_service(state, remoteport);
 			if (service)
-				vchiq_log_warning(vchiq_core_log_level,
-						  "%d: prs %s@%pK (%d->%d) - found connected service %d",
-						  state->id, msg_type_str(type), header,
-						  remoteport, localport, service->localport);
+				dev_warn(state->dev,
+					 "%d: prs %s@%pK (%d->%d) - found connected service %d",
+					 state->id, msg_type_str(type), header,
+					 remoteport, localport, service->localport);
 		}
 
 		if (!service) {
-			vchiq_log_error(vchiq_core_log_level,
-					"%d: prs %s@%pK (%d->%d) - invalid/closed service %d",
-					state->id, msg_type_str(type), header, remoteport,
-					localport, localport);
+			dev_err(state->dev,
+				"%d: prs %s@%pK (%d->%d) - invalid/closed service %d",
+				state->id, msg_type_str(type), header, remoteport,
+				localport, localport);
 			goto skip_message;
 		}
 		break;
@@ -1638,19 +1630,19 @@ parse_message(struct vchiq_state *state, struct vchiq_header *header)
 		svc_fourcc = service
 			? service->base.fourcc
 			: VCHIQ_MAKE_FOURCC('?', '?', '?', '?');
-		vchiq_log_info(SRVTRACE_LEVEL(service),
-			       "Rcvd Msg %s(%u) from %c%c%c%c s:%d d:%d len:%d",
-			       msg_type_str(type), type, VCHIQ_FOURCC_AS_4CHARS(svc_fourcc),
-			       remoteport, localport, size);
+		dev_info(service->state->dev,
+			 "Rcvd Msg %s(%u) from %c%c%c%c s:%d d:%d len:%d",
+			 msg_type_str(type), type, VCHIQ_FOURCC_AS_4CHARS(svc_fourcc),
+			 remoteport, localport, size);
 		if (size > 0)
 			vchiq_log_dump_mem("Rcvd", 0, header->data, min(16, size));
 	}
 
 	if (((unsigned long)header & VCHIQ_SLOT_MASK) +
 	    calc_stride(size) > VCHIQ_SLOT_SIZE) {
-		vchiq_log_error(vchiq_core_log_level,
-				"header %pK (msgid %x) - size %x too big for slot",
-				header, (unsigned int)msgid, (unsigned int)size);
+		dev_err(service->state->dev,
+			"header %pK (msgid %x) - size %x too big for slot",
+			header, (unsigned int)msgid, (unsigned int)size);
 		WARN(1, "oversized for slot\n");
 	}
 
@@ -1667,36 +1659,36 @@ parse_message(struct vchiq_state *state, struct vchiq_header *header)
 				header->data;
 			service->peer_version = payload->version;
 		}
-		vchiq_log_info(vchiq_core_log_level, "%d: prs OPENACK@%pK,%x (%d->%d) v:%d",
-			       state->id, header, size, remoteport, localport,
-			       service->peer_version);
+		dev_info(state->dev, "%d: prs OPENACK@%pK,%x (%d->%d) v:%d",
+			 state->id, header, size, remoteport, localport,
+			 service->peer_version);
 		if (service->srvstate == VCHIQ_SRVSTATE_OPENING) {
 			service->remoteport = remoteport;
 			set_service_state(service, VCHIQ_SRVSTATE_OPEN);
 			complete(&service->remove_event);
 		} else {
-			vchiq_log_error(vchiq_core_log_level, "OPENACK received in state %s",
-					srvstate_names[service->srvstate]);
+			dev_err(state->dev, "OPENACK received in state %s",
+				srvstate_names[service->srvstate]);
 		}
 		break;
 	case VCHIQ_MSG_CLOSE:
 		WARN_ON(size); /* There should be no data */
 
-		vchiq_log_info(vchiq_core_log_level, "%d: prs CLOSE@%pK (%d->%d)",
-			       state->id, header, remoteport, localport);
+		dev_info(state->dev, "%d: prs CLOSE@%pK (%d->%d)",
+			 state->id, header, remoteport, localport);
 
 		mark_service_closing_internal(service, 1);
 
 		if (vchiq_close_service_internal(service, CLOSE_RECVD) == -EAGAIN)
 			goto bail_not_ready;
 
-		vchiq_log_info(vchiq_core_log_level, "Close Service %c%c%c%c s:%u d:%d",
-			       VCHIQ_FOURCC_AS_4CHARS(service->base.fourcc),
-			       service->localport, service->remoteport);
+		dev_info(state->dev, "Close Service %c%c%c%c s:%u d:%d",
+			 VCHIQ_FOURCC_AS_4CHARS(service->base.fourcc),
+			 service->localport, service->remoteport);
 		break;
 	case VCHIQ_MSG_DATA:
-		vchiq_log_info(vchiq_core_log_level, "%d: prs DATA@%pK,%x (%d->%d)",
-			       state->id, header, size, remoteport, localport);
+		dev_info(state->dev, "%d: prs DATA@%pK,%x (%d->%d)",
+			 state->id, header, size, remoteport, localport);
 
 		if ((service->remoteport == remoteport) &&
 		    (service->srvstate == VCHIQ_SRVSTATE_OPEN)) {
@@ -1715,7 +1707,7 @@ parse_message(struct vchiq_state *state, struct vchiq_header *header)
 		}
 		break;
 	case VCHIQ_MSG_CONNECT:
-		vchiq_log_info(vchiq_core_log_level, "%d: prs CONNECT@%pK", state->id, header);
+		dev_info(state->dev, "%d: prs CONNECT@%pK", state->id, header);
 		state->version_common =	((struct vchiq_slot_zero *)
 					 state->slot_data)->version;
 		complete(&state->connect);
@@ -1746,19 +1738,17 @@ parse_message(struct vchiq_state *state, struct vchiq_header *header)
 			}
 			if ((int)(queue->remote_insert -
 				queue->local_insert) >= 0) {
-				vchiq_log_error(vchiq_core_log_level,
-						"%d: prs %s@%pK (%d->%d) unexpected (ri=%d,li=%d)",
-						state->id, msg_type_str(type), header, remoteport,
-						localport, queue->remote_insert,
-						queue->local_insert);
+				dev_err(state->dev,
+					"%d: prs %s@%pK (%d->%d) unexpected (ri=%d,li=%d)",
+					state->id, msg_type_str(type), header, remoteport,
+					localport, queue->remote_insert,
+					queue->local_insert);
 				mutex_unlock(&service->bulk_mutex);
 				break;
 			}
 			if (queue->process != queue->remote_insert) {
-				pr_err("%s: p %x != ri %x\n",
-				       __func__,
-				       queue->process,
-				       queue->remote_insert);
+				pr_err("%s: p %x != ri %x\n", __func__,
+				       queue->process, queue->remote_insert);
 				mutex_unlock(&service->bulk_mutex);
 				goto bail_not_ready;
 			}
@@ -1767,14 +1757,14 @@ parse_message(struct vchiq_state *state, struct vchiq_header *header)
 			bulk->actual = *(int *)header->data;
 			queue->remote_insert++;
 
-			vchiq_log_info(vchiq_core_log_level, "%d: prs %s@%pK (%d->%d) %x@%pad",
-				       state->id, msg_type_str(type), header, remoteport, localport,
-				       bulk->actual, &bulk->data);
+			dev_info(state->dev, "%d: prs %s@%pK (%d->%d) %x@%pad",
+				 state->id, msg_type_str(type), header, remoteport, localport,
+				 bulk->actual, &bulk->data);
 
-			vchiq_log_trace(vchiq_core_log_level, "%d: prs:%d %cx li=%x ri=%x p=%x",
-					state->id, localport,
-					(type == VCHIQ_MSG_BULK_RX_DONE) ? 'r' : 't',
-					queue->local_insert, queue->remote_insert, queue->process);
+			dev_dbg(state->dev, "%d: prs:%d %cx li=%x ri=%x p=%x",
+				state->id, localport,
+				(type == VCHIQ_MSG_BULK_RX_DONE) ? 'r' : 't',
+				queue->local_insert, queue->remote_insert, queue->process);
 
 			DEBUG_TRACE(PARSE_LINE);
 			WARN_ON(queue->process == queue->local_insert);
@@ -1787,16 +1777,14 @@ parse_message(struct vchiq_state *state, struct vchiq_header *header)
 		}
 		break;
 	case VCHIQ_MSG_PADDING:
-		vchiq_log_trace(vchiq_core_log_level, "%d: prs PADDING@%pK,%x",
-				state->id, header, size);
+		dev_dbg(state->dev, "%d: prs PADDING@%pK,%x", state->id, header, size);
 		break;
 	case VCHIQ_MSG_PAUSE:
 		/* If initiated, signal the application thread */
-		vchiq_log_trace(vchiq_core_log_level, "%d: prs PAUSE@%pK,%x",
-				state->id, header, size);
+		dev_dbg(state->dev, "%d: prs PAUSE@%pK,%x", state->id, header, size);
 		if (state->conn_state == VCHIQ_CONNSTATE_PAUSED) {
-			vchiq_log_error(vchiq_core_log_level, "%d: PAUSE received in state PAUSED",
-					state->id);
+			dev_dbg(state->dev, "%d: PAUSE received in state PAUSED",
+				state->id);
 			break;
 		}
 		if (state->conn_state != VCHIQ_CONNSTATE_PAUSE_SENT) {
@@ -1809,8 +1797,7 @@ parse_message(struct vchiq_state *state, struct vchiq_header *header)
 		vchiq_set_conn_state(state, VCHIQ_CONNSTATE_PAUSED);
 		break;
 	case VCHIQ_MSG_RESUME:
-		vchiq_log_trace(vchiq_core_log_level, "%d: prs RESUME@%pK,%x",
-				state->id, header, size);
+		dev_dbg(state->dev, "%d: prs RESUME@%pK,%x", state->id, header, size);
 		/* Release the slot mutex */
 		mutex_unlock(&state->slot_mutex);
 		vchiq_set_conn_state(state, VCHIQ_CONNSTATE_CONNECTED);
@@ -1826,8 +1813,8 @@ parse_message(struct vchiq_state *state, struct vchiq_header *header)
 		break;
 
 	default:
-		vchiq_log_error(vchiq_core_log_level, "%d: prs invalid msgid %x@%pK,%x",
-				state->id, msgid, header, size);
+		dev_err(state->dev, "%d: prs invalid msgid %x@%pK,%x",
+			state->id, msgid, header, size);
 		WARN(1, "invalid message\n");
 		break;
 	}
@@ -1937,7 +1924,7 @@ handle_poll(struct vchiq_state *state)
 			 * since the PAUSE should have flushed
 			 * through outstanding messages.
 			 */
-			vchiq_log_error(vchiq_core_log_level, "Failed to send RESUME message");
+			dev_info(state->dev, "Failed to send RESUME message");
 		}
 		break;
 	default:
@@ -2036,10 +2023,10 @@ sync_func(void *v)
 		service = find_service_by_port(state, localport);
 
 		if (!service) {
-			vchiq_log_error(vchiq_sync_log_level,
-					"%d: sf %s@%pK (%d->%d) - invalid/closed service %d",
-					state->id, msg_type_str(type), header,
-					remoteport, localport, localport);
+			dev_err(state->dev,
+				"%d: sf %s@%pK (%d->%d) - invalid/closed service %d",
+				state->id, msg_type_str(type), header,
+				remoteport, localport, localport);
 			release_message_sync(state, header);
 			continue;
 		}
@@ -2050,10 +2037,10 @@ sync_func(void *v)
 			svc_fourcc = service
 				? service->base.fourcc
 				: VCHIQ_MAKE_FOURCC('?', '?', '?', '?');
-			vchiq_log_trace(vchiq_sync_log_level,
-					"Rcvd Msg %s from %c%c%c%c s:%d d:%d len:%d",
-					msg_type_str(type), VCHIQ_FOURCC_AS_4CHARS(svc_fourcc),
-					remoteport, localport, size);
+			dev_dbg(state->dev,
+				"Rcvd Msg %s from %c%c%c%c s:%d d:%d len:%d",
+				msg_type_str(type), VCHIQ_FOURCC_AS_4CHARS(svc_fourcc),
+				remoteport, localport, size);
 			if (size > 0)
 				vchiq_log_dump_mem("Rcvd", 0, header->data, min(16, size));
 		}
@@ -2066,9 +2053,9 @@ sync_func(void *v)
 					header->data;
 				service->peer_version = payload->version;
 			}
-			vchiq_log_info(vchiq_sync_log_level, "%d: sf OPENACK@%pK,%x (%d->%d) v:%d",
-				       state->id, header, size, remoteport, localport,
-				       service->peer_version);
+			dev_info(state->dev, "%d: sf OPENACK@%pK,%x (%d->%d) v:%d",
+				 state->id, header, size, remoteport, localport,
+				 service->peer_version);
 			if (service->srvstate == VCHIQ_SRVSTATE_OPENING) {
 				service->remoteport = remoteport;
 				set_service_state(service, VCHIQ_SRVSTATE_OPENSYNC);
@@ -2079,22 +2066,22 @@ sync_func(void *v)
 			break;
 
 		case VCHIQ_MSG_DATA:
-			vchiq_log_trace(vchiq_sync_log_level, "%d: sf DATA@%pK,%x (%d->%d)",
-					state->id, header, size, remoteport, localport);
+			dev_dbg(state->dev, "%d: sf DATA@%pK,%x (%d->%d)",
+				state->id, header, size, remoteport, localport);
 
 			if ((service->remoteport == remoteport) &&
 			    (service->srvstate == VCHIQ_SRVSTATE_OPENSYNC)) {
 				if (make_service_callback(service, VCHIQ_MESSAGE_AVAILABLE, header,
 							  NULL) == -EAGAIN)
-					vchiq_log_error(vchiq_sync_log_level,
-							"synchronous callback to service %d returns -EAGAIN",
-							localport);
+					dev_err(state->dev,
+						"synchronous callback to service %d returns -EAGAIN",
+						localport);
 			}
 			break;
 
 		default:
-			vchiq_log_error(vchiq_sync_log_level, "%d: sf unexpected msgid %x@%pK,%x",
-					state->id, msgid, header, size);
+			dev_err(state->dev, "%d: sf unexpected msgid %x@%pK,%x",
+				state->id, msgid, header, size);
 			release_message_sync(state, header);
 			break;
 		}
@@ -2127,8 +2114,7 @@ vchiq_init_slots(void *mem_base, int mem_size)
 	num_slots -= first_data_slot;
 
 	if (num_slots < 4) {
-		vchiq_log_error(vchiq_core_log_level, "%s - insufficient memory %x bytes",
-				__func__, mem_size);
+		pr_err("vchiq: %s - insufficient memory %x bytes", __func__, mem_size);
 		return NULL;
 	}
 
@@ -2164,12 +2150,10 @@ vchiq_init_state(struct vchiq_state *state, struct vchiq_slot_zero *slot_zero, s
 	remote = &slot_zero->master;
 
 	if (local->initialised) {
-		vchiq_loud_error_header();
 		if (remote->initialised)
-			vchiq_loud_error("local state has already been initialised");
+			pr_err("vchiq: local state has already been initialised");
 		else
-			vchiq_loud_error("master/slave mismatch two slaves");
-		vchiq_loud_error_footer();
+			pr_err("vchiq: master/slave mismatch two slaves");
 		return -EINVAL;
 	}
 
@@ -2247,9 +2231,7 @@ vchiq_init_state(struct vchiq_state *state, struct vchiq_slot_zero *slot_zero, s
 	state->slot_handler_thread = kthread_create(&slot_handler_func, (void *)state, threadname);
 
 	if (IS_ERR(state->slot_handler_thread)) {
-		vchiq_loud_error_header();
-		vchiq_loud_error("couldn't create thread %s", threadname);
-		vchiq_loud_error_footer();
+		pr_err("vchiq: couldn't create thread %s", threadname);
 		return PTR_ERR(state->slot_handler_thread);
 	}
 	set_user_nice(state->slot_handler_thread, -19);
@@ -2257,9 +2239,7 @@ vchiq_init_state(struct vchiq_state *state, struct vchiq_slot_zero *slot_zero, s
 	snprintf(threadname, sizeof(threadname), "vchiq-recy/%d", state->id);
 	state->recycle_thread = kthread_create(&recycle_func, (void *)state, threadname);
 	if (IS_ERR(state->recycle_thread)) {
-		vchiq_loud_error_header();
-		vchiq_loud_error("couldn't create thread %s", threadname);
-		vchiq_loud_error_footer();
+		pr_err("vchiq: couldn't create thread %s", threadname);
 		ret = PTR_ERR(state->recycle_thread);
 		goto fail_free_handler_thread;
 	}
@@ -2268,9 +2248,7 @@ vchiq_init_state(struct vchiq_state *state, struct vchiq_slot_zero *slot_zero, s
 	snprintf(threadname, sizeof(threadname), "vchiq-sync/%d", state->id);
 	state->sync_thread = kthread_create(&sync_func, (void *)state, threadname);
 	if (IS_ERR(state->sync_thread)) {
-		vchiq_loud_error_header();
-		vchiq_loud_error("couldn't create thread %s", threadname);
-		vchiq_loud_error_footer();
+		pr_err("vchiq: couldn't create thread %s", threadname);
 		ret = PTR_ERR(state->sync_thread);
 		goto fail_free_recycle_thread;
 	}
@@ -2346,7 +2324,7 @@ EXPORT_SYMBOL(vchiq_msg_hold);
 static int vchiq_validate_params(const struct vchiq_service_params_kernel *params)
 {
 	if (!params->callback || !params->fourcc) {
-		vchiq_loud_error("Can't add service, invalid params\n");
+		pr_err("vchiq: Can't add service, invalid params\n");
 		return -EINVAL;
 	}
 
@@ -2476,9 +2454,9 @@ vchiq_add_service_internal(struct vchiq_state *state,
 	/* Bring this service online */
 	set_service_state(service, srvstate);
 
-	vchiq_log_info(vchiq_core_msg_log_level, "%s Service %c%c%c%c SrcPort:%d",
-		       (srvstate == VCHIQ_SRVSTATE_OPENING) ? "Open" : "Add",
-		       VCHIQ_FOURCC_AS_4CHARS(params->fourcc), service->localport);
+	pr_info("vchiq: %s Service %c%c%c%c SrcPort:%d",
+		(srvstate == VCHIQ_SRVSTATE_OPENING) ? "Open" : "Add",
+		VCHIQ_FOURCC_AS_4CHARS(params->fourcc), service->localport);
 
 	/* Don't unlock the service - leave it with a ref_count of 1. */
 
@@ -2515,11 +2493,11 @@ vchiq_open_service_internal(struct vchiq_service *service, int client_id)
 	} else if ((service->srvstate != VCHIQ_SRVSTATE_OPEN) &&
 		   (service->srvstate != VCHIQ_SRVSTATE_OPENSYNC)) {
 		if (service->srvstate != VCHIQ_SRVSTATE_CLOSEWAIT)
-			vchiq_log_error(vchiq_core_log_level,
-					"%d: osi - srvstate = %s (ref %u)",
-					service->state->id,
-					srvstate_names[service->srvstate],
-					kref_read(&service->ref_count));
+			dev_err(service->state->dev,
+				"%d: osi - srvstate = %s (ref %u)",
+				service->state->id,
+				srvstate_names[service->srvstate],
+				kref_read(&service->ref_count));
 		status = -EINVAL;
 		VCHIQ_SERVICE_STATS_INC(service, error_count);
 		vchiq_release_service_internal(service);
@@ -2574,14 +2552,14 @@ release_service_messages(struct vchiq_service *service)
 			int port = VCHIQ_MSG_DSTPORT(msgid);
 
 			if ((port == service->localport) && (msgid & VCHIQ_MSGID_CLAIMED)) {
-				vchiq_log_info(vchiq_core_log_level, "  fsi - hdr %pK", header);
+				dev_info(state->dev, "  fsi - hdr %pK", header);
 				release_slot(state, slot_info, header, NULL);
 			}
 			pos += calc_stride(header->size);
 			if (pos > VCHIQ_SLOT_SIZE) {
-				vchiq_log_error(vchiq_core_log_level,
-						"fsi - pos %x: header %pK, msgid %x, header->msgid %x, header->size %x",
-						pos, header, msgid, header->msgid, header->size);
+				dev_err(state->dev,
+					"fsi - pos %x: header %pK, msgid %x, header->msgid %x, header->size %x",
+					pos, header, msgid, header->msgid, header->size);
 				WARN(1, "invalid slot position\n");
 			}
 		}
@@ -2635,8 +2613,8 @@ close_service_complete(struct vchiq_service *service, int failstate)
 	case VCHIQ_SRVSTATE_LISTENING:
 		break;
 	default:
-		vchiq_log_error(vchiq_core_log_level, "%s(%x) called in state %s", __func__,
-				service->handle, srvstate_names[service->srvstate]);
+		dev_err(service->state->dev, "%s(%x) called in state %s", __func__,
+			service->handle, srvstate_names[service->srvstate]);
 		WARN(1, "%s in unexpected state\n", __func__);
 		return -EINVAL;
 	}
@@ -2682,8 +2660,8 @@ vchiq_close_service_internal(struct vchiq_service *service, int close_recvd)
 	int close_id = MAKE_CLOSE(service->localport,
 				  VCHIQ_MSG_DSTPORT(service->remoteport));
 
-	vchiq_log_info(vchiq_core_log_level, "%d: csi:%d,%d (%s)", service->state->id,
-		       service->localport, close_recvd, srvstate_names[service->srvstate]);
+	dev_err(state->dev, "%d: csi:%d,%d (%s)", service->state->id,
+		service->localport, close_recvd, srvstate_names[service->srvstate]);
 
 	switch (service->srvstate) {
 	case VCHIQ_SRVSTATE_CLOSED:
@@ -2691,8 +2669,8 @@ vchiq_close_service_internal(struct vchiq_service *service, int close_recvd)
 	case VCHIQ_SRVSTATE_LISTENING:
 	case VCHIQ_SRVSTATE_CLOSEWAIT:
 		if (close_recvd) {
-			vchiq_log_error(vchiq_core_log_level, "%s(1) called in state %s",
-					__func__, srvstate_names[service->srvstate]);
+			dev_err(state->dev, "%s(1) called in state %s",
+				__func__, srvstate_names[service->srvstate]);
 		} else if (is_server) {
 			if (service->srvstate == VCHIQ_SRVSTATE_LISTENING) {
 				status = -EINVAL;
@@ -2779,8 +2757,8 @@ vchiq_close_service_internal(struct vchiq_service *service, int close_recvd)
 		break;
 
 	default:
-		vchiq_log_error(vchiq_core_log_level, "%s(%d) called in state %s", __func__,
-				close_recvd, srvstate_names[service->srvstate]);
+		dev_err(state->dev, "%s(%d) called in state %s", __func__,
+			close_recvd, srvstate_names[service->srvstate]);
 		break;
 	}
 
@@ -2793,8 +2771,8 @@ vchiq_terminate_service_internal(struct vchiq_service *service)
 {
 	struct vchiq_state *state = service->state;
 
-	vchiq_log_info(vchiq_core_log_level, "%d: tsi - (%d<->%d)", state->id,
-		       service->localport, service->remoteport);
+	dev_info(state->dev, "%d: tsi - (%d<->%d)", state->id,
+		 service->localport, service->remoteport);
 
 	mark_service_closing(service);
 
@@ -2808,7 +2786,7 @@ vchiq_free_service_internal(struct vchiq_service *service)
 {
 	struct vchiq_state *state = service->state;
 
-	vchiq_log_info(vchiq_core_log_level, "%d: fsi - (%d)", state->id, service->localport);
+	dev_info(state->dev, "%d: fsi - (%d)", state->id, service->localport);
 
 	switch (service->srvstate) {
 	case VCHIQ_SRVSTATE_OPENING:
@@ -2818,8 +2796,8 @@ vchiq_free_service_internal(struct vchiq_service *service)
 	case VCHIQ_SRVSTATE_CLOSEWAIT:
 		break;
 	default:
-		vchiq_log_error(vchiq_core_log_level, "%d: fsi - (%d) in state %s", state->id,
-				service->localport, srvstate_names[service->srvstate]);
+		dev_err(state->dev, "%d: fsi - (%d) in state %s", state->id,
+			service->localport, srvstate_names[service->srvstate]);
 		return;
 	}
 
@@ -2888,8 +2866,8 @@ vchiq_close_service(struct vchiq_instance *instance, unsigned int handle)
 	if (!service)
 		return -EINVAL;
 
-	vchiq_log_info(vchiq_core_log_level, "%d: close_service:%d",
-		       service->state->id, service->localport);
+	dev_info(service->state->dev, "%d: close_service:%d",
+		 service->state->id, service->localport);
 
 	if ((service->srvstate == VCHIQ_SRVSTATE_FREE) ||
 	    (service->srvstate == VCHIQ_SRVSTATE_LISTENING) ||
@@ -2919,10 +2897,10 @@ vchiq_close_service(struct vchiq_instance *instance, unsigned int handle)
 		    (service->srvstate == VCHIQ_SRVSTATE_OPEN))
 			break;
 
-		vchiq_log_warning(vchiq_core_log_level,
-				  "%d: close_service:%d - waiting in state %s",
-				  service->state->id, service->localport,
-				  srvstate_names[service->srvstate]);
+		dev_warn(service->state->dev,
+			 "%d: close_service:%d - waiting in state %s",
+			 service->state->id, service->localport,
+			 srvstate_names[service->srvstate]);
 	}
 
 	if (!status &&
@@ -2946,8 +2924,8 @@ vchiq_remove_service(struct vchiq_instance *instance, unsigned int handle)
 	if (!service)
 		return -EINVAL;
 
-	vchiq_log_info(vchiq_core_log_level, "%d: remove_service:%d",
-		       service->state->id, service->localport);
+	dev_info(service->state->dev, "%d: remove_service:%d",
+		 service->state->id, service->localport);
 
 	if (service->srvstate == VCHIQ_SRVSTATE_FREE) {
 		vchiq_service_put(service);
@@ -2980,10 +2958,10 @@ vchiq_remove_service(struct vchiq_instance *instance, unsigned int handle)
 		    (service->srvstate == VCHIQ_SRVSTATE_OPEN))
 			break;
 
-		vchiq_log_warning(vchiq_core_log_level,
-				  "%d: remove_service:%d - waiting in state %s",
-				  service->state->id, service->localport,
-				  srvstate_names[service->srvstate]);
+		dev_warn(service->state->dev,
+			 "%d: remove_service:%d - waiting in state %s",
+			 service->state->id, service->localport,
+			 srvstate_names[service->srvstate]);
 	}
 
 	if (!status && (service->srvstate != VCHIQ_SRVSTATE_FREE))
@@ -3090,9 +3068,9 @@ int vchiq_bulk_transfer(struct vchiq_instance *instance, unsigned int handle,
 	 */
 	wmb();
 
-	vchiq_log_info(vchiq_core_log_level, "%d: bt (%d->%d) %cx %x@%pad %pK",
-		       state->id, service->localport, service->remoteport,
-		       dir_char, size, &bulk->data, userdata);
+	dev_info(state->dev, "%d: bt (%d->%d) %cx %x@%pad %pK",
+		 state->id, service->localport, service->remoteport,
+		 dir_char, size, &bulk->data, userdata);
 
 	/*
 	 * The slot mutex must be held when the service is being closed, so
@@ -3127,9 +3105,9 @@ int vchiq_bulk_transfer(struct vchiq_instance *instance, unsigned int handle,
 	mutex_unlock(&state->slot_mutex);
 	mutex_unlock(&service->bulk_mutex);
 
-	vchiq_log_trace(vchiq_core_log_level, "%d: bt:%d %cx li=%x ri=%x p=%x",
-			state->id, service->localport, dir_char, queue->local_insert,
-			queue->remote_insert, queue->process);
+	dev_err(state->dev, "%d: bt:%d %cx li=%x ri=%x p=%x",
+		state->id, service->localport, dir_char, queue->local_insert,
+		queue->remote_insert, queue->process);
 
 waiting:
 	vchiq_service_put(service);
@@ -3618,26 +3596,6 @@ int vchiq_dump_service_state(void *dump_context, struct vchiq_service *service)
 	return err;
 }
 
-void
-vchiq_loud_error_header(void)
-{
-	vchiq_log_error(vchiq_core_log_level,
-			"============================================================================");
-	vchiq_log_error(vchiq_core_log_level,
-			"============================================================================");
-	vchiq_log_error(vchiq_core_log_level, "=====");
-}
-
-void
-vchiq_loud_error_footer(void)
-{
-	vchiq_log_error(vchiq_core_log_level, "=====");
-	vchiq_log_error(vchiq_core_log_level,
-			"============================================================================");
-	vchiq_log_error(vchiq_core_log_level,
-			"============================================================================");
-}
-
 int vchiq_send_remote_use(struct vchiq_state *state)
 {
 	if (state->conn_state == VCHIQ_CONNSTATE_DISCONNECTED)
@@ -3684,9 +3642,9 @@ void vchiq_log_dump_mem(const char *label, u32 addr, const void *void_mem, size_
 		*s++ = '\0';
 
 		if (label && (*label != '\0'))
-			vchiq_log_trace(VCHIQ_LOG_TRACE, "%s: %08x: %s", label, addr, line_buf);
+			pr_debug("vchiq: %s: %08x: %s", label, addr, line_buf);
 		else
-			vchiq_log_trace(VCHIQ_LOG_TRACE, "%08x: %s", addr, line_buf);
+			pr_debug("vchiq: %08x: %s", addr, line_buf);
 
 		addr += 16;
 		mem += 16;
-- 
2.39.0

Re: [RFC PATCH 1/4] staging: vc04_services: vchiq_core: Drop custom logging

[Stefan Wahren]

Hi Umang,

Am 18.01.23 um 12:58 schrieb Umang Jain:
> Drop custom logging from the vchiq_core.c and use standard kernel
> logging infrastructure (dev_dbg() and friends for struct Device
> stuff) and pr_info (and similar) for vchiq_services/instances things.
i'm sorry but your "staging: vc04_services: vchiq: Register devices with 
a custom bus_type" is still in my backlog. I was busy with some 
regressions on bcm2835/bcm2711.
>
> Signed-off-by: Umang Jain <umang.jain@ideasonboard.com>
> ---
>   .../interface/vchiq_arm/vchiq_core.c          | 450 ++++++++----------
>   1 file changed, 204 insertions(+), 246 deletions(-)
>
> diff --git a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
> index 4e705a447a62..7b3c57326d28 100644
> --- a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
> +++ b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
> @@ -227,10 +227,11 @@ static const char *msg_type_str(unsigned int msg_type)
>   static inline void
>   set_service_state(struct vchiq_service *service, int newstate)
>   {
> -	vchiq_log_info(vchiq_core_log_level, "%d: srv:%d %s->%s",
> -		       service->state->id, service->localport,
> -		       srvstate_names[service->srvstate],
> -		       srvstate_names[newstate]);
> +	struct vchiq_state *state = service->state;
> +
> +	dev_info(state->dev, "%d: srv:%d %s->%s", state->id,
> +		 service->localport, srvstate_names[service->srvstate],
> +		 srvstate_names[newstate]);
>   	service->srvstate = newstate;
>   }
>   
> @@ -255,8 +256,7 @@ find_service_by_handle(struct vchiq_instance *instance, unsigned int handle)
>   		return service;
>   	}
>   	rcu_read_unlock();
> -	vchiq_log_info(vchiq_core_log_level,
> -		       "Invalid service handle 0x%x", handle);
> +	pr_info("vchiq: Invalid service handle 0x%x", handle);

Some log levels like this here doesn't make sense. I would expect here a 
warning or an error. Could you please have look at it in a separate patch?

Thanks

Re: [RFC PATCH 1/4] staging: vc04_services: vchiq_core: Drop custom logging

[Dan Carpenter]

On Wed, Jan 18, 2023 at 05:28:07PM +0530, Umang Jain wrote:
> diff --git a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
> index 4e705a447a62..7b3c57326d28 100644
> --- a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
> +++ b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
> @@ -227,10 +227,11 @@ static const char *msg_type_str(unsigned int msg_type)
>  static inline void
>  set_service_state(struct vchiq_service *service, int newstate)
>  {
> -	vchiq_log_info(vchiq_core_log_level, "%d: srv:%d %s->%s",
> -		       service->state->id, service->localport,
> -		       srvstate_names[service->srvstate],
> -		       srvstate_names[newstate]);
> +	struct vchiq_state *state = service->state;
> +
> +	dev_info(state->dev, "%d: srv:%d %s->%s", state->id,
> +		 service->localport, srvstate_names[service->srvstate],
> +		 srvstate_names[newstate]);

This should be a debug level printk.  Don't spam dmesg in the success
path.  Success should not be noteworthy.

>  	service->srvstate = newstate;
>  }

regards,
dan carpenter

[RFC PATCH 2/4] staging: vc04_services: vchiq_arm: Drop custom logging

[Umang Jain]

Drop custom logging from the vchiq_arm.c and use standard kernel
logging infrastructure (dev_dbg and friends for struct Device
stuff) and pr_info (and similar) for vchiq services/instances things.

Signed-off-by: Umang Jain <umang.jain@ideasonboard.com>
---
 .../interface/vchiq_arm/vchiq_arm.c           | 147 ++++++++----------
 1 file changed, 66 insertions(+), 81 deletions(-)

diff --git a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_arm.c b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_arm.c
index 86c8e5df7cf6..ed3773b996a3 100644
--- a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_arm.c
+++ b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_arm.c
@@ -296,7 +296,7 @@ create_pagelist(struct vchiq_instance *instance, char *buf, char __user *ubuf,
 	pagelist = dma_alloc_coherent(instance->state->dev, pagelist_size, &dma_addr,
 				      GFP_KERNEL);
 
-	vchiq_log_trace(vchiq_arm_log_level, "%s - %pK", __func__, pagelist);
+	dev_dbg(instance->state->dev, "%s - %pK", __func__, pagelist);
 
 	if (!pagelist)
 		return NULL;
@@ -351,9 +351,8 @@ create_pagelist(struct vchiq_instance *instance, char *buf, char __user *ubuf,
 						   type == PAGELIST_READ, pages);
 
 		if (actual_pages != num_pages) {
-			vchiq_log_info(vchiq_arm_log_level,
-				       "%s - only %d/%d pages locked",
-				       __func__, actual_pages, num_pages);
+			dev_info(instance->state->dev, "%s - only %d/%d pages locked",
+				 __func__, actual_pages, num_pages);
 
 			/* This is probably due to the process being killed */
 			if (actual_pages > 0)
@@ -447,8 +446,8 @@ free_pagelist(struct vchiq_instance *instance, struct vchiq_pagelist_info *pagel
 	struct page **pages = pagelistinfo->pages;
 	unsigned int num_pages = pagelistinfo->num_pages;
 
-	vchiq_log_trace(vchiq_arm_log_level, "%s - %pK, %d",
-			__func__, pagelistinfo->pagelist, actual);
+	dev_dbg(instance->state->dev, "%s - %pK, %d", __func__,
+		pagelistinfo->pagelist, actual);
 
 	/*
 	 * NOTE: dma_unmap_sg must be called before the
@@ -590,8 +589,8 @@ int vchiq_platform_init(struct platform_device *pdev, struct vchiq_state *state)
 		return err ? : -ENXIO;
 	}
 
-	vchiq_log_info(vchiq_arm_log_level, "vchiq_init - done (slots %pK, phys %pad)",
-		       vchiq_slot_zero, &slot_phys);
+	dev_info(dev, "vchiq_init - done (slots %pK, phys %pad)",
+		 vchiq_slot_zero, &slot_phys);
 
 	vchiq_call_connected_callbacks();
 
@@ -721,18 +720,16 @@ int vchiq_initialise(struct vchiq_instance **instance_out)
 		usleep_range(500, 600);
 	}
 	if (i == VCHIQ_INIT_RETRIES) {
-		vchiq_log_error(vchiq_core_log_level, "%s: videocore not initialized\n", __func__);
+		pr_err("vchiq: %s: videocore not initialized\n", __func__);
 		ret = -ENOTCONN;
 		goto failed;
 	} else if (i > 0) {
-		vchiq_log_warning(vchiq_core_log_level,
-				  "%s: videocore initialized after %d retries\n", __func__, i);
+		pr_warn("vchiq: %s: videocore initialized after %d retries\n", __func__, i);
 	}
 
 	instance = kzalloc(sizeof(*instance), GFP_KERNEL);
 	if (!instance) {
-		vchiq_log_error(vchiq_core_log_level,
-				"%s: error allocating vchiq instance\n", __func__);
+		pr_err("vchiq: %s: error allocating vchiq instance\n", __func__);
 		ret = -ENOMEM;
 		goto failed;
 	}
@@ -747,7 +744,7 @@ int vchiq_initialise(struct vchiq_instance **instance_out)
 	ret = 0;
 
 failed:
-	vchiq_log_trace(vchiq_core_log_level, "%s(%p): returning %d", __func__, instance, ret);
+	pr_debug("vchiq: %s(%p): returning %d", __func__, instance, ret);
 
 	return ret;
 }
@@ -760,8 +757,8 @@ void free_bulk_waiter(struct vchiq_instance *instance)
 	list_for_each_entry_safe(waiter, next,
 				 &instance->bulk_waiter_list, list) {
 		list_del(&waiter->list);
-		vchiq_log_info(vchiq_arm_log_level, "bulk_waiter - cleaned up %pK for pid %d",
-			       waiter, waiter->pid);
+		dev_info(instance->state->dev, "bulk_waiter - cleaned up %pK for pid %d",
+			 waiter, waiter->pid);
 		kfree(waiter);
 	}
 }
@@ -779,7 +776,7 @@ int vchiq_shutdown(struct vchiq_instance *instance)
 
 	mutex_unlock(&state->mutex);
 
-	vchiq_log_trace(vchiq_core_log_level, "%s(%p): returning %d", __func__, instance, status);
+	pr_debug("vchiq: %s(%p): returning %d", __func__, instance, status);
 
 	free_bulk_waiter(instance);
 	kfree(instance);
@@ -799,7 +796,7 @@ int vchiq_connect(struct vchiq_instance *instance)
 	struct vchiq_state *state = instance->state;
 
 	if (mutex_lock_killable(&state->mutex)) {
-		vchiq_log_trace(vchiq_core_log_level, "%s: call to mutex_lock failed", __func__);
+		pr_debug("vchiq: %s: call to mutex_lock failed", __func__);
 		status = -EAGAIN;
 		goto failed;
 	}
@@ -811,7 +808,7 @@ int vchiq_connect(struct vchiq_instance *instance)
 	mutex_unlock(&state->mutex);
 
 failed:
-	vchiq_log_trace(vchiq_core_log_level, "%s(%p): returning %d", __func__, instance, status);
+	pr_debug("vchiq: %s(%p): returning %d", __func__, instance, status);
 
 	return status;
 }
@@ -842,7 +839,7 @@ vchiq_add_service(struct vchiq_instance *instance,
 		status = -EINVAL;
 	}
 
-	vchiq_log_trace(vchiq_core_log_level, "%s(%p): returning %d", __func__, instance, status);
+	pr_debug("vchiq: %s(%p): returning %d", __func__, instance, status);
 
 	return status;
 }
@@ -873,7 +870,7 @@ vchiq_open_service(struct vchiq_instance *instance,
 	}
 
 failed:
-	vchiq_log_trace(vchiq_core_log_level, "%s(%p): returning %d", __func__, instance, status);
+	pr_debug("vchiq: %s(%p): returning %d", __func__, instance, status);
 
 	return status;
 }
@@ -997,7 +994,7 @@ vchiq_blocking_bulk_transfer(struct vchiq_instance *instance, unsigned int handl
 	} else {
 		waiter = kzalloc(sizeof(*waiter), GFP_KERNEL);
 		if (!waiter) {
-			vchiq_log_error(vchiq_core_log_level, "%s - out of memory", __func__);
+			dev_err(instance->state->dev, "%s - out of memory", __func__);
 			return -ENOMEM;
 		}
 	}
@@ -1020,8 +1017,8 @@ vchiq_blocking_bulk_transfer(struct vchiq_instance *instance, unsigned int handl
 		mutex_lock(&instance->bulk_waiter_list_mutex);
 		list_add(&waiter->list, &instance->bulk_waiter_list);
 		mutex_unlock(&instance->bulk_waiter_list_mutex);
-		vchiq_log_info(vchiq_arm_log_level, "saved bulk_waiter %pK for pid %d", waiter,
-			       current->pid);
+		dev_info(instance->state->dev, "saved bulk_waiter %pK for pid %d", waiter,
+			 current->pid);
 	}
 
 	return status;
@@ -1041,13 +1038,13 @@ add_completion(struct vchiq_instance *instance, enum vchiq_reason reason,
 	while ((insert - instance->completion_remove) >= MAX_COMPLETIONS) {
 		/* Out of space - wait for the client */
 		DEBUG_TRACE(SERVICE_CALLBACK_LINE);
-		vchiq_log_trace(vchiq_arm_log_level, "%s - completion queue full", __func__);
+		dev_dbg(instance->state->dev, "%s - completion queue full", __func__);
 		DEBUG_COUNT(COMPLETION_QUEUE_FULL_COUNT);
 		if (wait_for_completion_interruptible(&instance->remove_event)) {
-			vchiq_log_info(vchiq_arm_log_level, "service_callback interrupted");
+			dev_info(instance->state->dev, "service_callback interrupted");
 			return -EAGAIN;
 		} else if (instance->closing) {
-			vchiq_log_info(vchiq_arm_log_level, "service_callback closing");
+			dev_info(instance->state->dev, "service_callback closing");
 			return 0;
 		}
 		DEBUG_TRACE(SERVICE_CALLBACK_LINE);
@@ -1127,11 +1124,10 @@ service_callback(struct vchiq_instance *instance, enum vchiq_reason reason,
 	vchiq_service_get(service);
 	rcu_read_unlock();
 
-	vchiq_log_trace(vchiq_arm_log_level,
-			"%s - service %lx(%d,%p), reason %d, header %lx, instance %lx, bulk_userdata %lx",
-			__func__, (unsigned long)user_service, service->localport,
-			user_service->userdata, reason, (unsigned long)header,
-			(unsigned long)instance, (unsigned long)bulk_userdata);
+	dev_dbg(service->state->dev, "%s - service %lx(%d,%p), reason %d, header %lx, instance %lx, bulk_userdata %lx",
+		 __func__, (unsigned long)user_service, service->localport,
+		 user_service->userdata, reason, (unsigned long)header,
+		 (unsigned long)instance, (unsigned long)bulk_userdata);
 
 	if (header && user_service->is_vchi) {
 		spin_lock(&msg_queue_spinlock);
@@ -1140,7 +1136,7 @@ service_callback(struct vchiq_instance *instance, enum vchiq_reason reason,
 			spin_unlock(&msg_queue_spinlock);
 			DEBUG_TRACE(SERVICE_CALLBACK_LINE);
 			DEBUG_COUNT(MSG_QUEUE_FULL_COUNT);
-			vchiq_log_trace(vchiq_arm_log_level, "%s - msg queue full", __func__);
+			dev_dbg(service->state->dev, "%s - msg queue full", __func__);
 			/*
 			 * If there is no MESSAGE_AVAILABLE in the completion
 			 * queue, add one
@@ -1149,8 +1145,7 @@ service_callback(struct vchiq_instance *instance, enum vchiq_reason reason,
 				instance->completion_remove) < 0) {
 				int status;
 
-				vchiq_log_info(vchiq_arm_log_level,
-					       "Inserting extra MESSAGE_AVAILABLE");
+				dev_info(service->state->dev, "Inserting extra MESSAGE_AVAILABLE");
 				DEBUG_TRACE(SERVICE_CALLBACK_LINE);
 				status = add_completion(instance, reason, NULL, user_service,
 							bulk_userdata);
@@ -1163,12 +1158,12 @@ service_callback(struct vchiq_instance *instance, enum vchiq_reason reason,
 
 			DEBUG_TRACE(SERVICE_CALLBACK_LINE);
 			if (wait_for_completion_interruptible(&user_service->remove_event)) {
-				vchiq_log_info(vchiq_arm_log_level, "%s interrupted", __func__);
+				dev_info(service->state->dev, "%s interrupted", __func__);
 				DEBUG_TRACE(SERVICE_CALLBACK_LINE);
 				vchiq_service_put(service);
 				return -EAGAIN;
 			} else if (instance->closing) {
-				vchiq_log_info(vchiq_arm_log_level, "%s closing", __func__);
+				dev_info(service->state->dev, "%s closing", __func__);
 				DEBUG_TRACE(SERVICE_CALLBACK_LINE);
 				vchiq_service_put(service);
 				return -EINVAL;
@@ -1364,7 +1359,7 @@ vchiq_keepalive_vchiq_callback(struct vchiq_instance *instance,
 			       struct vchiq_header *header,
 			       unsigned int service_user, void *bulk_user)
 {
-	vchiq_log_error(vchiq_susp_log_level, "%s callback reason %d", __func__, reason);
+	dev_err(instance->state->dev, "%s callback reason %d", __func__, reason);
 	return 0;
 }
 
@@ -1388,22 +1383,19 @@ vchiq_keepalive_thread_func(void *v)
 
 	ret = vchiq_initialise(&instance);
 	if (ret) {
-		vchiq_log_error(vchiq_susp_log_level, "%s vchiq_initialise failed %d", __func__,
-				ret);
+		pr_err("vchiq: %s vchiq_initialise failed %d", __func__, ret);
 		goto exit;
 	}
 
 	status = vchiq_connect(instance);
 	if (status) {
-		vchiq_log_error(vchiq_susp_log_level, "%s vchiq_connect failed %d", __func__,
-				status);
+		pr_err("vchiq: %s vchiq_connect failed %d", __func__, status);
 		goto shutdown;
 	}
 
 	status = vchiq_add_service(instance, &params, &ka_handle);
 	if (status) {
-		vchiq_log_error(vchiq_susp_log_level, "%s vchiq_open_service failed %d", __func__,
-				status);
+		pr_err("vchiq: %s vchiq_open_service failed %d", __func__, status);
 		goto shutdown;
 	}
 
@@ -1411,7 +1403,7 @@ vchiq_keepalive_thread_func(void *v)
 		long rc = 0, uc = 0;
 
 		if (wait_for_completion_interruptible(&arm_state->ka_evt)) {
-			vchiq_log_error(vchiq_susp_log_level, "%s interrupted", __func__);
+			pr_err("vchiq: %s interrupted", __func__);
 			flush_signals(current);
 			continue;
 		}
@@ -1431,16 +1423,14 @@ vchiq_keepalive_thread_func(void *v)
 			atomic_inc(&arm_state->ka_use_ack_count);
 			status = vchiq_use_service(instance, ka_handle);
 			if (status) {
-				vchiq_log_error(vchiq_susp_log_level,
-						"%s vchiq_use_service error %d", __func__, status);
+				pr_err("vchiq: %s vchiq_use_service error %d", __func__, status);
 			}
 		}
 		while (rc--) {
 			status = vchiq_release_service(instance, ka_handle);
 			if (status) {
-				vchiq_log_error(vchiq_susp_log_level,
-						"%s vchiq_release_service error %d", __func__,
-						status);
+				pr_err("vchiq: %s vchiq_release_service error %d", __func__,
+					status);
 			}
 		}
 	}
@@ -1475,7 +1465,7 @@ vchiq_use_internal(struct vchiq_state *state, struct vchiq_service *service,
 			service->client_id);
 		entity_uc = &service->service_use_count;
 	} else {
-		vchiq_log_error(vchiq_susp_log_level, "%s null service ptr", __func__);
+		pr_err("vchiq: %s null service ptr", __func__);
 		ret = -EINVAL;
 		goto out;
 	}
@@ -1484,8 +1474,8 @@ vchiq_use_internal(struct vchiq_state *state, struct vchiq_service *service,
 	local_uc = ++arm_state->videocore_use_count;
 	++(*entity_uc);
 
-	vchiq_log_trace(vchiq_susp_log_level, "%s %s count %d, state count %d", __func__, entity,
-			*entity_uc, local_uc);
+	pr_debug("vchiq: %s %s count %d, state count %d", __func__, entity,
+		 *entity_uc, local_uc);
 
 	write_unlock_bh(&arm_state->susp_res_lock);
 
@@ -1504,7 +1494,7 @@ vchiq_use_internal(struct vchiq_state *state, struct vchiq_service *service,
 	}
 
 out:
-	vchiq_log_trace(vchiq_susp_log_level, "%s exit %d", __func__, ret);
+	pr_debug("vchiq: %s exit %d", __func__, ret);
 	return ret;
 }
 
@@ -1542,14 +1532,14 @@ vchiq_release_internal(struct vchiq_state *state, struct vchiq_service *service)
 	--arm_state->videocore_use_count;
 	--(*entity_uc);
 
-	vchiq_log_trace(vchiq_susp_log_level, "%s %s count %d, state count %d", __func__, entity,
-			*entity_uc, arm_state->videocore_use_count);
+	pr_debug("vchiq: %s %s count %d, state count %d", __func__, entity,
+		 *entity_uc, arm_state->videocore_use_count);
 
 unlock:
 	write_unlock_bh(&arm_state->susp_res_lock);
 
 out:
-	vchiq_log_trace(vchiq_susp_log_level, "%s exit %d", __func__, ret);
+	pr_debug("vchiq: %s exit %d", __func__, ret);
 	return ret;
 }
 
@@ -1723,18 +1713,17 @@ vchiq_dump_service_use_state(struct vchiq_state *state)
 	read_unlock_bh(&arm_state->susp_res_lock);
 
 	if (only_nonzero)
-		vchiq_log_warning(vchiq_susp_log_level, "Too many active services (%d). Only dumping up to first %d services with non-zero use-count",
-				  active_services, found);
+		pr_warn("vchiq: Too many active services (%d). Only dumping up to first %d services with non-zero use-count",
+			active_services, found);
 
 	for (i = 0; i < found; i++) {
-		vchiq_log_warning(vchiq_susp_log_level, "----- %c%c%c%c:%d service count %d %s",
-				  VCHIQ_FOURCC_AS_4CHARS(service_data[i].fourcc),
-				  service_data[i].clientid, service_data[i].use_count,
-				  service_data[i].use_count ? nz : "");
+		pr_warn("vchiq: %c%c%c%c:%d service count %d %s",
+			VCHIQ_FOURCC_AS_4CHARS(service_data[i].fourcc),
+			service_data[i].clientid, service_data[i].use_count,
+			service_data[i].use_count ? nz : "");
 	}
-	vchiq_log_warning(vchiq_susp_log_level, "----- VCHIQ use count %d", peer_count);
-	vchiq_log_warning(vchiq_susp_log_level, "--- Overall vchiq instance use count %d",
-			  vc_use_count);
+	pr_warn("vchiq: VCHIQ use count %d", peer_count);
+	pr_warn("vchiq: Overall vchiq instance use count %d", vc_use_count);
 
 	kfree(service_data);
 }
@@ -1756,10 +1745,9 @@ vchiq_check_service(struct vchiq_service *service)
 	read_unlock_bh(&arm_state->susp_res_lock);
 
 	if (ret) {
-		vchiq_log_error(vchiq_susp_log_level,
-				"%s ERROR - %c%c%c%c:%d service count %d, state count %d", __func__,
-				VCHIQ_FOURCC_AS_4CHARS(service->base.fourcc), service->client_id,
-				service->service_use_count, arm_state->videocore_use_count);
+		pr_err("vchiq: %s ERROR - %c%c%c%c:%d service count %d, state count %d", __func__,
+			VCHIQ_FOURCC_AS_4CHARS(service->base.fourcc), service->client_id,
+			service->service_use_count, arm_state->videocore_use_count);
 		vchiq_dump_service_use_state(service->state);
 	}
 out:
@@ -1773,8 +1761,8 @@ void vchiq_platform_conn_state_changed(struct vchiq_state *state,
 	struct vchiq_arm_state *arm_state = vchiq_platform_get_arm_state(state);
 	char threadname[16];
 
-	vchiq_log_info(vchiq_susp_log_level, "%d: %s->%s", state->id,
-		       get_conn_state_name(oldstate), get_conn_state_name(newstate));
+	dev_info(state->dev, "%d: %s->%s", state->id, get_conn_state_name(oldstate),
+		 get_conn_state_name(newstate));
 	if (state->conn_state != VCHIQ_CONNSTATE_CONNECTED)
 		return;
 
@@ -1792,9 +1780,8 @@ void vchiq_platform_conn_state_changed(struct vchiq_state *state,
 					      (void *)state,
 					      threadname);
 	if (IS_ERR(arm_state->ka_thread)) {
-		vchiq_log_error(vchiq_susp_log_level,
-				"vchiq: FATAL: couldn't create thread %s",
-				threadname);
+		dev_crit(state->dev, "vchiq: FATAL: couldn't create thread %s",
+			 threadname);
 	} else {
 		wake_up_process(arm_state->ka_thread);
 	}
@@ -1887,9 +1874,8 @@ static int vchiq_probe(struct platform_device *pdev)
 
 	vchiq_debugfs_init();
 
-	vchiq_log_info(vchiq_arm_log_level,
-		       "vchiq: platform initialised - version %d (min %d)",
-		       VCHIQ_VERSION, VCHIQ_VERSION_MIN);
+	dev_info(&pdev->dev, "vchiq: platform initialised - version %d (min %d)",
+		 VCHIQ_VERSION, VCHIQ_VERSION_MIN);
 
 	/*
 	 * Simply exit on error since the function handles cleanup in
@@ -1897,8 +1883,7 @@ static int vchiq_probe(struct platform_device *pdev)
 	 */
 	err = vchiq_register_chrdev(&pdev->dev);
 	if (err) {
-		vchiq_log_warning(vchiq_arm_log_level,
-				  "Failed to initialize vchiq cdev");
+		dev_warn(&pdev->dev, "Failed to initialize vchiq cdev");
 		goto error_exit;
 	}
 
@@ -1912,7 +1897,7 @@ static int vchiq_probe(struct platform_device *pdev)
 	return 0;
 
 failed_platform_init:
-	vchiq_log_warning(vchiq_arm_log_level, "could not initialize vchiq platform");
+	pr_warn("vchiq: could not initialize vchiq platform\n");
 error_exit:
 	return err;
 }
-- 
2.39.0

[RFC PATCH 3/4] staging: vc04_services: Drop custom logging

[Umang Jain]

Drop custom logging from the vchiq_connected and vchiq_dev.
Use standard kernel logging infrastructure (dev_dbg and friends
for struct Device stuff) and pr_info (and similar) for vchiq_instance
related things.

Signed-off-by: Umang Jain <umang.jain@ideasonboard.com>
---
 .../interface/vchiq_arm/vchiq_connected.c     |  5 +-
 .../interface/vchiq_arm/vchiq_dev.c           | 78 ++++++++-----------
 2 files changed, 33 insertions(+), 50 deletions(-)

diff --git a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_connected.c b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_connected.c
index bdb0ab617d8b..c769014ae2ac 100644
--- a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_connected.c
+++ b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_connected.c
@@ -39,9 +39,8 @@ void vchiq_add_connected_callback(void (*callback)(void))
 		callback();
 	} else {
 		if (g_num_deferred_callbacks >= MAX_CALLBACKS) {
-			vchiq_log_error(vchiq_core_log_level,
-					"There already %d callback registered - please increase MAX_CALLBACKS",
-					g_num_deferred_callbacks);
+			pr_err("vchiq: There is already %d callback registered - please increase MAX_CALLBACKS",
+				g_num_deferred_callbacks);
 		} else {
 			g_deferred_callback[g_num_deferred_callbacks] =
 				callback;
diff --git a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_dev.c b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_dev.c
index 841e1a535642..2524a435e5ce 100644
--- a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_dev.c
+++ b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_dev.c
@@ -47,9 +47,8 @@ user_service_free(void *userdata)
 
 static void close_delivered(struct user_service *user_service)
 {
-	vchiq_log_info(vchiq_arm_log_level,
-		       "%s(handle=%x)",
-		       __func__, user_service->service->handle);
+	pr_info("vchiq: %s(handle=%x)", __func__,
+		user_service->service->handle);
 
 	if (user_service->close_pending) {
 		/* Allow the underlying service to be culled */
@@ -235,8 +234,7 @@ static int vchiq_ioc_dequeue_message(struct vchiq_instance *instance,
 			spin_unlock(&msg_queue_spinlock);
 			DEBUG_TRACE(DEQUEUE_MESSAGE_LINE);
 			if (wait_for_completion_interruptible(&user_service->insert_event)) {
-				vchiq_log_info(vchiq_arm_log_level,
-					       "DEQUEUE_MESSAGE interrupted");
+				pr_info("vchiq: DEQUEUE_MESSAGE interrupted\n");
 				ret = -EINTR;
 				break;
 			}
@@ -271,9 +269,8 @@ static int vchiq_ioc_dequeue_message(struct vchiq_instance *instance,
 			ret = -EFAULT;
 		}
 	} else {
-		vchiq_log_error(vchiq_arm_log_level,
-				"header %pK: bufsize %x < size %x",
-				header, args->bufsize, header->size);
+		pr_err("vchiq: header %pK: bufsize %x < size %x",
+			header, args->bufsize, header->size);
 		WARN(1, "invalid size\n");
 		ret = -EMSGSIZE;
 	}
@@ -318,13 +315,11 @@ static int vchiq_irq_queue_bulk_tx_rx(struct vchiq_instance *instance,
 		}
 		mutex_unlock(&instance->bulk_waiter_list_mutex);
 		if (!waiter) {
-			vchiq_log_error(vchiq_arm_log_level,
-					"no bulk_waiter found for pid %d", current->pid);
+			pr_err("vchiq: no bulk_waiter found for pid %d", current->pid);
 			ret = -ESRCH;
 			goto out;
 		}
-		vchiq_log_info(vchiq_arm_log_level,
-			       "found bulk_waiter %pK for pid %d", waiter, current->pid);
+		pr_info("vchiq: found bulk_waiter %pK for pid %d", waiter, current->pid);
 		userdata = &waiter->bulk_waiter;
 	} else {
 		userdata = args->userdata;
@@ -355,8 +350,7 @@ static int vchiq_irq_queue_bulk_tx_rx(struct vchiq_instance *instance,
 		mutex_lock(&instance->bulk_waiter_list_mutex);
 		list_add(&waiter->list, &instance->bulk_waiter_list);
 		mutex_unlock(&instance->bulk_waiter_list_mutex);
-		vchiq_log_info(vchiq_arm_log_level,
-			       "saved bulk_waiter %pK for pid %d", waiter, current->pid);
+		pr_info("vchiq: saved bulk_waiter %pK for pid %d", waiter, current->pid);
 
 		ret = put_user(mode_waiting, mode);
 	}
@@ -455,8 +449,7 @@ static int vchiq_ioc_await_completion(struct vchiq_instance *instance,
 		mutex_lock(&instance->completion_mutex);
 		if (rc) {
 			DEBUG_TRACE(AWAIT_COMPLETION_LINE);
-			vchiq_log_info(vchiq_arm_log_level,
-				       "AWAIT_COMPLETION interrupted");
+			pr_info("vchiq: AWAIT_COMPLETION interrupted");
 			ret = -EINTR;
 			goto out;
 		}
@@ -501,10 +494,9 @@ static int vchiq_ioc_await_completion(struct vchiq_instance *instance,
 			msglen = header->size + sizeof(struct vchiq_header);
 			/* This must be a VCHIQ-style service */
 			if (args->msgbufsize < msglen) {
-				vchiq_log_error(vchiq_arm_log_level,
-						"header %pK: msgbufsize %x < msglen %x",
-						header, args->msgbufsize, msglen);
-						WARN(1, "invalid message size\n");
+				pr_err("vchiq: header %pK: msgbufsize %x < msglen %x",
+				       header, args->msgbufsize, msglen);
+				       WARN(1, "invalid message size\n");
 				if (ret == 0)
 					ret = -EMSGSIZE;
 				break;
@@ -582,10 +574,9 @@ vchiq_ioctl(struct file *file, unsigned int cmd, unsigned long arg)
 	long ret = 0;
 	int i, rc;
 
-	vchiq_log_trace(vchiq_arm_log_level,
-			"%s - instance %pK, cmd %s, arg %lx", __func__, instance,
-			((_IOC_TYPE(cmd) == VCHIQ_IOC_MAGIC) && (_IOC_NR(cmd) <= VCHIQ_IOC_MAX)) ?
-			ioctl_names[_IOC_NR(cmd)] : "<invalid>", arg);
+	pr_debug("vchiq: %s - instance %pK, cmd %s, arg %lx", __func__, instance,
+		 ((_IOC_TYPE(cmd) == VCHIQ_IOC_MAGIC) && (_IOC_NR(cmd) <= VCHIQ_IOC_MAX)) ?
+		 ioctl_names[_IOC_NR(cmd)] : "<invalid>", arg);
 
 	switch (cmd) {
 	case VCHIQ_IOC_SHUTDOWN:
@@ -618,9 +609,8 @@ vchiq_ioctl(struct file *file, unsigned int cmd, unsigned long arg)
 		}
 		rc = mutex_lock_killable(&instance->state->mutex);
 		if (rc) {
-			vchiq_log_error(vchiq_arm_log_level,
-					"vchiq: connect: could not lock mutex for state %d: %d",
-					instance->state->id, rc);
+			pr_err("vchiq: connect: could not lock mutex for state %d: %d",
+			       instance->state->id, rc);
 			ret = -EINTR;
 			break;
 		}
@@ -630,8 +620,7 @@ vchiq_ioctl(struct file *file, unsigned int cmd, unsigned long arg)
 		if (!status)
 			instance->connected = 1;
 		else
-			vchiq_log_error(vchiq_arm_log_level,
-					"vchiq: could not connect: %d", status);
+			pr_err("vchiq: could not connect: %d", status);
 		break;
 
 	case VCHIQ_IOC_CREATE_SERVICE: {
@@ -700,11 +689,10 @@ vchiq_ioctl(struct file *file, unsigned int cmd, unsigned long arg)
 				vchiq_use_service_internal(service) :
 				vchiq_release_service_internal(service);
 			if (ret) {
-				vchiq_log_error(vchiq_susp_log_level,
-						"%s: cmd %s returned error %ld for service %c%c%c%c:%03d",
-						__func__, (cmd == VCHIQ_IOC_USE_SERVICE) ?
-						"VCHIQ_IOC_USE_SERVICE" :
-						"VCHIQ_IOC_RELEASE_SERVICE",
+				pr_err("vchiq:%s: cmd %s returned error %ld for service %c%c%c%c:%03d",
+					__func__, (cmd == VCHIQ_IOC_USE_SERVICE) ?
+					"VCHIQ_IOC_USE_SERVICE" :
+					"VCHIQ_IOC_RELEASE_SERVICE",
 					ret,
 					VCHIQ_FOURCC_AS_4CHARS(service->base.fourcc),
 					service->client_id);
@@ -869,15 +857,13 @@ vchiq_ioctl(struct file *file, unsigned int cmd, unsigned long arg)
 	}
 
 	if (!status && (ret < 0) && (ret != -EINTR) && (ret != -EWOULDBLOCK))
-		vchiq_log_info(vchiq_arm_log_level,
-			       "  ioctl instance %pK, cmd %s -> status %d, %ld",
-			       instance, (_IOC_NR(cmd) <= VCHIQ_IOC_MAX) ?
-			       ioctl_names[_IOC_NR(cmd)] : "<invalid>", status, ret);
+		pr_info("vchiq: ioctl instance %pK, cmd %s -> status %d, %ld",
+			instance, (_IOC_NR(cmd) <= VCHIQ_IOC_MAX) ?
+			ioctl_names[_IOC_NR(cmd)] : "<invalid>", status, ret);
 	else
-		vchiq_log_trace(vchiq_arm_log_level,
-				"  ioctl instance %pK, cmd %s -> status %d, %ld",
-				instance, (_IOC_NR(cmd) <= VCHIQ_IOC_MAX) ?
-				ioctl_names[_IOC_NR(cmd)] : "<invalid>", status, ret);
+		pr_debug("vchiq: ioctl instance %pK, cmd %s -> status %d, %ld",
+			instance, (_IOC_NR(cmd) <= VCHIQ_IOC_MAX) ?
+			ioctl_names[_IOC_NR(cmd)] : "<invalid>", status, ret);
 
 	return ret;
 }
@@ -1170,11 +1156,10 @@ static int vchiq_open(struct inode *inode, struct file *file)
 	struct vchiq_state *state = vchiq_get_state();
 	struct vchiq_instance *instance;
 
-	vchiq_log_info(vchiq_arm_log_level, "vchiq_open");
+	pr_info("vchiq: %s\n", __func__);
 
 	if (!state) {
-		vchiq_log_error(vchiq_arm_log_level,
-				"vchiq has no connection to VideoCore");
+		pr_err("vchiq: vchiq has no connection to VideoCore\n");
 		return -ENOTCONN;
 	}
 
@@ -1206,8 +1191,7 @@ static int vchiq_release(struct inode *inode, struct file *file)
 	int ret = 0;
 	int i;
 
-	vchiq_log_info(vchiq_arm_log_level, "%s: instance=%lx", __func__,
-		       (unsigned long)instance);
+	pr_info("%s: instance=%lx", __func__, (unsigned long)instance);
 
 	if (!state) {
 		ret = -EPERM;
-- 
2.39.0

[RFC PATCH 4/4] staging: vc04_services: Drop remnants of custom logging

[Umang Jain]

Drop remnants of custom logging such as header definitions and such.
Also migrate the vchiq_debugfs to use the log levels coming from
include/linux/kern_levels.h instead.

Signed-off-by: Umang Jain <umang.jain@ideasonboard.com>
---
 .../interface/vchiq_arm/vchiq_arm.c           |  4 --
 .../interface/vchiq_arm/vchiq_core.c          | 39 +++++++------------
 .../interface/vchiq_arm/vchiq_core.h          | 39 -------------------
 .../interface/vchiq_arm/vchiq_debugfs.c       | 26 ++++++++-----
 4 files changed, 31 insertions(+), 77 deletions(-)

diff --git a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_arm.c b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_arm.c
index ed3773b996a3..45e28ca368ee 100644
--- a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_arm.c
+++ b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_arm.c
@@ -60,10 +60,6 @@
 #define KEEPALIVE_VER 1
 #define KEEPALIVE_VER_MIN KEEPALIVE_VER
 
-/* Run time control of log level, based on KERN_XXX level. */
-int vchiq_arm_log_level = VCHIQ_LOG_DEFAULT;
-int vchiq_susp_log_level = VCHIQ_LOG_ERROR;
-
 DEFINE_SPINLOCK(msg_queue_spinlock);
 struct vchiq_state g_state;
 
diff --git a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
index 7b3c57326d28..4cf710a3ca28 100644
--- a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
+++ b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
@@ -9,6 +9,7 @@
 #include <linux/wait.h>
 #include <linux/delay.h>
 #include <linux/slab.h>
+#include <linux/kern_levels.h>
 #include <linux/kref.h>
 #include <linux/rcupdate.h>
 #include <linux/sched/signal.h>
@@ -103,10 +104,8 @@ static_assert((unsigned int)VCHIQ_PORT_MAX <
 
 #define BULK_INDEX(x) ((x) & (VCHIQ_NUM_SERVICE_BULKS - 1))
 
-#define SRVTRACE_LEVEL(srv) \
-	(((srv) && (srv)->trace) ? VCHIQ_LOG_TRACE : vchiq_core_msg_log_level)
 #define SRVTRACE_ENABLED(srv, lev) \
-	(((srv) && (srv)->trace) || (vchiq_core_msg_log_level >= (lev)))
+	(((srv) && (srv)->trace) || (LOGLEVEL_DEFAULT >= (lev)))
 
 #define NO_CLOSE_RECVD	0
 #define CLOSE_RECVD	1
@@ -154,11 +153,6 @@ static inline void check_sizes(void)
 	BUILD_BUG_ON_NOT_POWER_OF_2(VCHIQ_MAX_SERVICES);
 }
 
-/* Run time control of log level, based on KERN_XXX level. */
-int vchiq_core_log_level = VCHIQ_LOG_DEFAULT;
-int vchiq_core_msg_log_level = VCHIQ_LOG_DEFAULT;
-int vchiq_sync_log_level = VCHIQ_LOG_DEFAULT;
-
 DEFINE_SPINLOCK(bulk_waiter_spinlock);
 static DEFINE_SPINLOCK(quota_spinlock);
 
@@ -1035,8 +1029,7 @@ queue_message(struct vchiq_state *state, struct vchiq_service *service,
 			return -EINVAL;
 		}
 
-		if (SRVTRACE_ENABLED(service,
-				     VCHIQ_LOG_INFO))
+		if (SRVTRACE_ENABLED(service, LOGLEVEL_INFO))
 			vchiq_log_dump_mem("Sent", 0,
 					   header->data,
 					   min_t(size_t, 16, callback_result));
@@ -1144,6 +1137,7 @@ queue_message_sync(struct vchiq_state *state, struct vchiq_service *service,
 	struct vchiq_shared_state *local;
 	struct vchiq_header *header;
 	ssize_t callback_result;
+	int svc_fourcc;
 
 	local = state->local;
 
@@ -1184,8 +1178,7 @@ queue_message_sync(struct vchiq_state *state, struct vchiq_service *service,
 	}
 
 	if (service) {
-		if (SRVTRACE_ENABLED(service,
-				     VCHIQ_LOG_INFO))
+		if (SRVTRACE_ENABLED(service, LOGLEVEL_INFO))
 			vchiq_log_dump_mem("Sent", 0,
 					   header->data,
 					   min_t(size_t, 16, callback_result));
@@ -1199,19 +1192,15 @@ queue_message_sync(struct vchiq_state *state, struct vchiq_service *service,
 	header->size = size;
 	header->msgid = msgid;
 
-	if (vchiq_sync_log_level >= VCHIQ_LOG_TRACE) {
-		int svc_fourcc;
 
-		svc_fourcc = service
-			? service->base.fourcc
-			: VCHIQ_MAKE_FOURCC('?', '?', '?', '?');
+	svc_fourcc = service ? service->base.fourcc
+			     : VCHIQ_MAKE_FOURCC('?', '?', '?', '?');
 
-		dev_dbg(state->dev,
-			"Sent Sync Msg %s(%u) to %c%c%c%c s:%u d:%d len:%d",
-			msg_type_str(VCHIQ_MSG_TYPE(msgid)), VCHIQ_MSG_TYPE(msgid),
-			VCHIQ_FOURCC_AS_4CHARS(svc_fourcc), VCHIQ_MSG_SRCPORT(msgid),
-			VCHIQ_MSG_DSTPORT(msgid), size);
-	}
+	dev_dbg(state->dev,
+		"Sent Sync Msg %s(%u) to %c%c%c%c s:%u d:%d len:%d",
+		msg_type_str(VCHIQ_MSG_TYPE(msgid)), VCHIQ_MSG_TYPE(msgid),
+		VCHIQ_FOURCC_AS_4CHARS(svc_fourcc), VCHIQ_MSG_SRCPORT(msgid),
+		VCHIQ_MSG_DSTPORT(msgid), size);
 
 	remote_event_signal(&state->remote->sync_trigger);
 
@@ -1624,7 +1613,7 @@ parse_message(struct vchiq_state *state, struct vchiq_header *header)
 		break;
 	}
 
-	if (SRVTRACE_ENABLED(service, VCHIQ_LOG_INFO)) {
+	if (SRVTRACE_ENABLED(service, LOGLEVEL_INFO)) {
 		int svc_fourcc;
 
 		svc_fourcc = service
@@ -2031,7 +2020,7 @@ sync_func(void *v)
 			continue;
 		}
 
-		if (vchiq_sync_log_level >= VCHIQ_LOG_TRACE) {
+		if (vchiq_sync_log_level >= LOGLEVEL_DEBUG) {
 			int svc_fourcc;
 
 			svc_fourcc = service
diff --git a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.h b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.h
index ec3505424718..960bf4efeab5 100644
--- a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.h
+++ b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.h
@@ -30,39 +30,6 @@
 #define VCHIQ_SLOT_SIZE     4096
 #define VCHIQ_MAX_MSG_SIZE  (VCHIQ_SLOT_SIZE - sizeof(struct vchiq_header))
 
-/* Run time control of log level, based on KERN_XXX level. */
-#define VCHIQ_LOG_DEFAULT  4
-#define VCHIQ_LOG_ERROR    3
-#define VCHIQ_LOG_WARNING  4
-#define VCHIQ_LOG_INFO     6
-#define VCHIQ_LOG_TRACE    7
-
-#define VCHIQ_LOG_PREFIX   KERN_INFO "vchiq: "
-
-#ifndef vchiq_log_error
-#define vchiq_log_error(cat, fmt, ...) \
-	do { if (cat >= VCHIQ_LOG_ERROR) \
-		printk(VCHIQ_LOG_PREFIX fmt "\n", ##__VA_ARGS__); } while (0)
-#endif
-#ifndef vchiq_log_warning
-#define vchiq_log_warning(cat, fmt, ...) \
-	do { if (cat >= VCHIQ_LOG_WARNING) \
-		 printk(VCHIQ_LOG_PREFIX fmt "\n", ##__VA_ARGS__); } while (0)
-#endif
-#ifndef vchiq_log_info
-#define vchiq_log_info(cat, fmt, ...) \
-	do { if (cat >= VCHIQ_LOG_INFO) \
-		printk(VCHIQ_LOG_PREFIX fmt "\n", ##__VA_ARGS__); } while (0)
-#endif
-#ifndef vchiq_log_trace
-#define vchiq_log_trace(cat, fmt, ...) \
-	do { if (cat >= VCHIQ_LOG_TRACE) \
-		printk(VCHIQ_LOG_PREFIX fmt "\n", ##__VA_ARGS__); } while (0)
-#endif
-
-#define vchiq_loud_error(...) \
-	vchiq_log_error(vchiq_core_log_level, "===== " __VA_ARGS__)
-
 #define VCHIQ_SLOT_MASK        (VCHIQ_SLOT_SIZE - 1)
 #define VCHIQ_SLOT_QUEUE_MASK  (VCHIQ_MAX_SLOTS_PER_SIDE - 1)
 #define VCHIQ_SLOT_ZERO_SLOTS  DIV_ROUND_UP(sizeof(struct vchiq_slot_zero), \
@@ -496,12 +463,6 @@ vchiq_dump_state(void *dump_context, struct vchiq_state *state);
 extern int
 vchiq_dump_service_state(void *dump_context, struct vchiq_service *service);
 
-extern void
-vchiq_loud_error_header(void);
-
-extern void
-vchiq_loud_error_footer(void);
-
 extern void
 request_poll(struct vchiq_state *state, struct vchiq_service *service,
 	     int poll_type);
diff --git a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_debugfs.c b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_debugfs.c
index dc667afd1f8c..1d142752351d 100644
--- a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_debugfs.c
+++ b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_debugfs.c
@@ -5,6 +5,8 @@
  */
 
 #include <linux/debugfs.h>
+#include <linux/kern_levels.h>
+
 #include "vchiq_core.h"
 #include "vchiq_arm.h"
 #include "vchiq_debugfs.h"
@@ -22,6 +24,12 @@
 static struct dentry *vchiq_dbg_dir;
 static struct dentry *vchiq_dbg_clients;
 
+int vchiq_arm_log_level = LOGLEVEL_DEFAULT;
+int vchiq_susp_log_level = LOGLEVEL_ERR;
+int vchiq_core_log_level = LOGLEVEL_DEFAULT;
+int vchiq_core_msg_log_level = LOGLEVEL_DEFAULT;
+int vchiq_sync_log_level = LOGLEVEL_DEFAULT;
+
 /* Log category debugfs entries */
 struct vchiq_debugfs_log_entry {
 	const char *name;
@@ -42,16 +50,16 @@ static int debugfs_log_show(struct seq_file *f, void *offset)
 	char *log_value = NULL;
 
 	switch (*levp) {
-	case VCHIQ_LOG_ERROR:
+	case LOGLEVEL_ERR:
 		log_value = VCHIQ_LOG_ERROR_STR;
 		break;
-	case VCHIQ_LOG_WARNING:
+	case LOGLEVEL_WARNING:
 		log_value = VCHIQ_LOG_WARNING_STR;
 		break;
-	case VCHIQ_LOG_INFO:
+	case LOGLEVEL_INFO:
 		log_value = VCHIQ_LOG_INFO_STR;
 		break;
-	case VCHIQ_LOG_TRACE:
+	case LOGLEVEL_DEBUG:
 		log_value = VCHIQ_LOG_TRACE_STR;
 		break;
 	default:
@@ -85,15 +93,15 @@ static ssize_t debugfs_log_write(struct file *file,
 	kbuf[count - 1] = 0;
 
 	if (strncmp("error", kbuf, strlen("error")) == 0)
-		*levp = VCHIQ_LOG_ERROR;
+		*levp = LOGLEVEL_ERR;
 	else if (strncmp("warning", kbuf, strlen("warning")) == 0)
-		*levp = VCHIQ_LOG_WARNING;
+		*levp = LOGLEVEL_WARNING;
 	else if (strncmp("info", kbuf, strlen("info")) == 0)
-		*levp = VCHIQ_LOG_INFO;
+		*levp = LOGLEVEL_INFO;
 	else if (strncmp("trace", kbuf, strlen("trace")) == 0)
-		*levp = VCHIQ_LOG_TRACE;
+		*levp = LOGLEVEL_DEBUG;
 	else
-		*levp = VCHIQ_LOG_DEFAULT;
+		*levp = LOGLEVEL_DEFAULT;
 
 	*ppos += count;
 
-- 
2.39.0

Re: [RFC PATCH 4/4] staging: vc04_services: Drop remnants of custom logging

[Stefan Wahren]

Hi Umang,

[add Phil]

Am 18.01.23 um 12:58 schrieb Umang Jain:
> Drop remnants of custom logging such as header definitions and such.
> Also migrate the vchiq_debugfs to use the log levels coming from
> include/linux/kern_levels.h instead.
since we switch to default kernel logging, i would prefer to drop all of 
these logging specific debugfs entries too. Or just leave one entry to 
specify a logging mask as suggested before.
>
> Signed-off-by: Umang Jain <umang.jain@ideasonboard.com>
> ---
>   .../interface/vchiq_arm/vchiq_arm.c           |  4 --
>   .../interface/vchiq_arm/vchiq_core.c          | 39 +++++++------------
>   .../interface/vchiq_arm/vchiq_core.h          | 39 -------------------
>   .../interface/vchiq_arm/vchiq_debugfs.c       | 26 ++++++++-----
>   4 files changed, 31 insertions(+), 77 deletions(-)
>
> diff --git a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_arm.c b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_arm.c
> index ed3773b996a3..45e28ca368ee 100644
> --- a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_arm.c
> +++ b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_arm.c
> @@ -60,10 +60,6 @@
>   #define KEEPALIVE_VER 1
>   #define KEEPALIVE_VER_MIN KEEPALIVE_VER
>   
> -/* Run time control of log level, based on KERN_XXX level. */
> -int vchiq_arm_log_level = VCHIQ_LOG_DEFAULT;
> -int vchiq_susp_log_level = VCHIQ_LOG_ERROR;
> -
>   DEFINE_SPINLOCK(msg_queue_spinlock);
>   struct vchiq_state g_state;
>   
> diff --git a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
> index 7b3c57326d28..4cf710a3ca28 100644
> --- a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
> +++ b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.c
> @@ -9,6 +9,7 @@
>   #include <linux/wait.h>
>   #include <linux/delay.h>
>   #include <linux/slab.h>
> +#include <linux/kern_levels.h>
>   #include <linux/kref.h>
>   #include <linux/rcupdate.h>
>   #include <linux/sched/signal.h>
> @@ -103,10 +104,8 @@ static_assert((unsigned int)VCHIQ_PORT_MAX <
>   
>   #define BULK_INDEX(x) ((x) & (VCHIQ_NUM_SERVICE_BULKS - 1))
>   
> -#define SRVTRACE_LEVEL(srv) \
> -	(((srv) && (srv)->trace) ? VCHIQ_LOG_TRACE : vchiq_core_msg_log_level)
>   #define SRVTRACE_ENABLED(srv, lev) \
> -	(((srv) && (srv)->trace) || (vchiq_core_msg_log_level >= (lev)))
> +	(((srv) && (srv)->trace) || (LOGLEVEL_DEFAULT >= (lev)))
>   
>   #define NO_CLOSE_RECVD	0
>   #define CLOSE_RECVD	1
> @@ -154,11 +153,6 @@ static inline void check_sizes(void)
>   	BUILD_BUG_ON_NOT_POWER_OF_2(VCHIQ_MAX_SERVICES);
>   }
>   
> -/* Run time control of log level, based on KERN_XXX level. */
> -int vchiq_core_log_level = VCHIQ_LOG_DEFAULT;
> -int vchiq_core_msg_log_level = VCHIQ_LOG_DEFAULT;
> -int vchiq_sync_log_level = VCHIQ_LOG_DEFAULT;
> -
>   DEFINE_SPINLOCK(bulk_waiter_spinlock);
>   static DEFINE_SPINLOCK(quota_spinlock);
>   
> @@ -1035,8 +1029,7 @@ queue_message(struct vchiq_state *state, struct vchiq_service *service,
>   			return -EINVAL;
>   		}
>   
> -		if (SRVTRACE_ENABLED(service,
> -				     VCHIQ_LOG_INFO))
> +		if (SRVTRACE_ENABLED(service, LOGLEVEL_INFO))
>   			vchiq_log_dump_mem("Sent", 0,
>   					   header->data,
>   					   min_t(size_t, 16, callback_result));
> @@ -1144,6 +1137,7 @@ queue_message_sync(struct vchiq_state *state, struct vchiq_service *service,
>   	struct vchiq_shared_state *local;
>   	struct vchiq_header *header;
>   	ssize_t callback_result;
> +	int svc_fourcc;
>   
>   	local = state->local;
>   
> @@ -1184,8 +1178,7 @@ queue_message_sync(struct vchiq_state *state, struct vchiq_service *service,
>   	}
>   
>   	if (service) {
> -		if (SRVTRACE_ENABLED(service,
> -				     VCHIQ_LOG_INFO))
> +		if (SRVTRACE_ENABLED(service, LOGLEVEL_INFO))
>   			vchiq_log_dump_mem("Sent", 0,
>   					   header->data,
>   					   min_t(size_t, 16, callback_result));
> @@ -1199,19 +1192,15 @@ queue_message_sync(struct vchiq_state *state, struct vchiq_service *service,
>   	header->size = size;
>   	header->msgid = msgid;
>   
> -	if (vchiq_sync_log_level >= VCHIQ_LOG_TRACE) {
> -		int svc_fourcc;
>   
> -		svc_fourcc = service
> -			? service->base.fourcc
> -			: VCHIQ_MAKE_FOURCC('?', '?', '?', '?');
> +	svc_fourcc = service ? service->base.fourcc
> +			     : VCHIQ_MAKE_FOURCC('?', '?', '?', '?');
>   
> -		dev_dbg(state->dev,
> -			"Sent Sync Msg %s(%u) to %c%c%c%c s:%u d:%d len:%d",
> -			msg_type_str(VCHIQ_MSG_TYPE(msgid)), VCHIQ_MSG_TYPE(msgid),
> -			VCHIQ_FOURCC_AS_4CHARS(svc_fourcc), VCHIQ_MSG_SRCPORT(msgid),
> -			VCHIQ_MSG_DSTPORT(msgid), size);
> -	}
> +	dev_dbg(state->dev,
> +		"Sent Sync Msg %s(%u) to %c%c%c%c s:%u d:%d len:%d",
> +		msg_type_str(VCHIQ_MSG_TYPE(msgid)), VCHIQ_MSG_TYPE(msgid),
> +		VCHIQ_FOURCC_AS_4CHARS(svc_fourcc), VCHIQ_MSG_SRCPORT(msgid),
> +		VCHIQ_MSG_DSTPORT(msgid), size);
>   
>   	remote_event_signal(&state->remote->sync_trigger);
>   
> @@ -1624,7 +1613,7 @@ parse_message(struct vchiq_state *state, struct vchiq_header *header)
>   		break;
>   	}
>   
> -	if (SRVTRACE_ENABLED(service, VCHIQ_LOG_INFO)) {
> +	if (SRVTRACE_ENABLED(service, LOGLEVEL_INFO)) {
>   		int svc_fourcc;
>   
>   		svc_fourcc = service
> @@ -2031,7 +2020,7 @@ sync_func(void *v)
>   			continue;
>   		}
>   
> -		if (vchiq_sync_log_level >= VCHIQ_LOG_TRACE) {
> +		if (vchiq_sync_log_level >= LOGLEVEL_DEBUG) {
>   			int svc_fourcc;
>   
>   			svc_fourcc = service
> diff --git a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.h b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.h
> index ec3505424718..960bf4efeab5 100644
> --- a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.h
> +++ b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_core.h
> @@ -30,39 +30,6 @@
>   #define VCHIQ_SLOT_SIZE     4096
>   #define VCHIQ_MAX_MSG_SIZE  (VCHIQ_SLOT_SIZE - sizeof(struct vchiq_header))
>   
> -/* Run time control of log level, based on KERN_XXX level. */
> -#define VCHIQ_LOG_DEFAULT  4
> -#define VCHIQ_LOG_ERROR    3
> -#define VCHIQ_LOG_WARNING  4
> -#define VCHIQ_LOG_INFO     6
> -#define VCHIQ_LOG_TRACE    7
> -
> -#define VCHIQ_LOG_PREFIX   KERN_INFO "vchiq: "
> -
> -#ifndef vchiq_log_error
> -#define vchiq_log_error(cat, fmt, ...) \
> -	do { if (cat >= VCHIQ_LOG_ERROR) \
> -		printk(VCHIQ_LOG_PREFIX fmt "\n", ##__VA_ARGS__); } while (0)
> -#endif
> -#ifndef vchiq_log_warning
> -#define vchiq_log_warning(cat, fmt, ...) \
> -	do { if (cat >= VCHIQ_LOG_WARNING) \
> -		 printk(VCHIQ_LOG_PREFIX fmt "\n", ##__VA_ARGS__); } while (0)
> -#endif
> -#ifndef vchiq_log_info
> -#define vchiq_log_info(cat, fmt, ...) \
> -	do { if (cat >= VCHIQ_LOG_INFO) \
> -		printk(VCHIQ_LOG_PREFIX fmt "\n", ##__VA_ARGS__); } while (0)
> -#endif
> -#ifndef vchiq_log_trace
> -#define vchiq_log_trace(cat, fmt, ...) \
> -	do { if (cat >= VCHIQ_LOG_TRACE) \
> -		printk(VCHIQ_LOG_PREFIX fmt "\n", ##__VA_ARGS__); } while (0)
> -#endif
> -
> -#define vchiq_loud_error(...) \
> -	vchiq_log_error(vchiq_core_log_level, "===== " __VA_ARGS__)
> -
>   #define VCHIQ_SLOT_MASK        (VCHIQ_SLOT_SIZE - 1)
>   #define VCHIQ_SLOT_QUEUE_MASK  (VCHIQ_MAX_SLOTS_PER_SIDE - 1)
>   #define VCHIQ_SLOT_ZERO_SLOTS  DIV_ROUND_UP(sizeof(struct vchiq_slot_zero), \
> @@ -496,12 +463,6 @@ vchiq_dump_state(void *dump_context, struct vchiq_state *state);
>   extern int
>   vchiq_dump_service_state(void *dump_context, struct vchiq_service *service);
>   
> -extern void
> -vchiq_loud_error_header(void);
> -
> -extern void
> -vchiq_loud_error_footer(void);
> -
>   extern void
>   request_poll(struct vchiq_state *state, struct vchiq_service *service,
>   	     int poll_type);
> diff --git a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_debugfs.c b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_debugfs.c
> index dc667afd1f8c..1d142752351d 100644
> --- a/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_debugfs.c
> +++ b/drivers/staging/vc04_services/interface/vchiq_arm/vchiq_debugfs.c
> @@ -5,6 +5,8 @@
>    */
>   
>   #include <linux/debugfs.h>
> +#include <linux/kern_levels.h>
> +
>   #include "vchiq_core.h"
>   #include "vchiq_arm.h"
>   #include "vchiq_debugfs.h"
> @@ -22,6 +24,12 @@
>   static struct dentry *vchiq_dbg_dir;
>   static struct dentry *vchiq_dbg_clients;
>   
> +int vchiq_arm_log_level = LOGLEVEL_DEFAULT;
> +int vchiq_susp_log_level = LOGLEVEL_ERR;
> +int vchiq_core_log_level = LOGLEVEL_DEFAULT;
> +int vchiq_core_msg_log_level = LOGLEVEL_DEFAULT;
> +int vchiq_sync_log_level = LOGLEVEL_DEFAULT;
> +
>   /* Log category debugfs entries */
>   struct vchiq_debugfs_log_entry {
>   	const char *name;
> @@ -42,16 +50,16 @@ static int debugfs_log_show(struct seq_file *f, void *offset)
>   	char *log_value = NULL;
>   
>   	switch (*levp) {
> -	case VCHIQ_LOG_ERROR:
> +	case LOGLEVEL_ERR:
>   		log_value = VCHIQ_LOG_ERROR_STR;
>   		break;
> -	case VCHIQ_LOG_WARNING:
> +	case LOGLEVEL_WARNING:
>   		log_value = VCHIQ_LOG_WARNING_STR;
>   		break;
> -	case VCHIQ_LOG_INFO:
> +	case LOGLEVEL_INFO:
>   		log_value = VCHIQ_LOG_INFO_STR;
>   		break;
> -	case VCHIQ_LOG_TRACE:
> +	case LOGLEVEL_DEBUG:
>   		log_value = VCHIQ_LOG_TRACE_STR;
>   		break;
>   	default:
> @@ -85,15 +93,15 @@ static ssize_t debugfs_log_write(struct file *file,
>   	kbuf[count - 1] = 0;
>   
>   	if (strncmp("error", kbuf, strlen("error")) == 0)
> -		*levp = VCHIQ_LOG_ERROR;
> +		*levp = LOGLEVEL_ERR;
>   	else if (strncmp("warning", kbuf, strlen("warning")) == 0)
> -		*levp = VCHIQ_LOG_WARNING;
> +		*levp = LOGLEVEL_WARNING;
>   	else if (strncmp("info", kbuf, strlen("info")) == 0)
> -		*levp = VCHIQ_LOG_INFO;
> +		*levp = LOGLEVEL_INFO;
>   	else if (strncmp("trace", kbuf, strlen("trace")) == 0)
> -		*levp = VCHIQ_LOG_TRACE;
> +		*levp = LOGLEVEL_DEBUG;
>   	else
> -		*levp = VCHIQ_LOG_DEFAULT;
> +		*levp = LOGLEVEL_DEFAULT;
>   
>   	*ppos += count;
>   

Re: [RFC PATCH 0/4] Drop custom logging

[Stefan Wahren]

Hi Umang,

[add Phil]

Am 18.01.23 um 12:58 schrieb Umang Jain:
> Drop custom logging from the vchiq interface.
> Mostly of them are replaced with dev_dbg and friends
> and/or pr_info and friends.
>
> The debugfs log levels (in 4/4) are mapped to kernel
> logs levels (coming from include/linux/kern_levels.h)
> Would like some thoughts on it as I am not sure (hence
> marking this is RFC)
>
>  From drivers/staging/vc04_services/interface/TODO:
>
> """
> * Cleanup logging mechanism
>
> The driver should probably be using the standard kernel logging mechanisms
> such as dev_info, dev_dbg, and friends.

i don't have any experience with vchiq logging/debug. So i'm not sure if 
it's acceptable to lose the second log level dimension (like 
vchiq_arm_log_level) completely. Complex drivers like brcmfmac have a 
debug mask to avoid log spamming [1]. Maybe this is a compromise.

Btw some loglevel locations has already been messed up during 
refactoring :-(

[1] - drivers/net/wireless/broadcom/brcm80211/brcmfmac/debug.h

> """
>
> Umang Jain (4):
>    staging: vc04_services: vchiq_core: Drop custom logging
>    staging: vc04_services: vchiq_arm: Drop custom logging
>    staging: vc04_services: Drop custom logging
>    staging: vc04_services: Drop remnants of custom logging
>
>   .../interface/vchiq_arm/vchiq_arm.c           | 151 +++---
>   .../interface/vchiq_arm/vchiq_connected.c     |   5 +-
>   .../interface/vchiq_arm/vchiq_core.c          | 479 ++++++++----------
>   .../interface/vchiq_arm/vchiq_core.h          |  39 --
>   .../interface/vchiq_arm/vchiq_debugfs.c       |  26 +-
>   .../interface/vchiq_arm/vchiq_dev.c           |  78 ++-
>   6 files changed, 329 insertions(+), 449 deletions(-)
>

Re: [RFC PATCH 0/4] Drop custom logging

[Dan Carpenter]

On Wed, Jan 18, 2023 at 06:54:56PM +0100, Stefan Wahren wrote:
> Hi Umang,
> 
> [add Phil]
> 
> Am 18.01.23 um 12:58 schrieb Umang Jain:
> > Drop custom logging from the vchiq interface.
> > Mostly of them are replaced with dev_dbg and friends
> > and/or pr_info and friends.
> > 
> > The debugfs log levels (in 4/4) are mapped to kernel
> > logs levels (coming from include/linux/kern_levels.h)
> > Would like some thoughts on it as I am not sure (hence
> > marking this is RFC)
> > 
> >  From drivers/staging/vc04_services/interface/TODO:
> > 
> > """
> > * Cleanup logging mechanism
> > 
> > The driver should probably be using the standard kernel logging mechanisms
> > such as dev_info, dev_dbg, and friends.
> 
> i don't have any experience with vchiq logging/debug. So i'm not sure if
> it's acceptable to lose the second log level dimension (like
> vchiq_arm_log_level) completely. Complex drivers like brcmfmac have a debug
> mask to avoid log spamming [1]. Maybe this is a compromise.
> 
> Btw some loglevel locations has already been messed up during refactoring
> :-(
> 
> [1] - drivers/net/wireless/broadcom/brcm80211/brcmfmac/debug.h
> 

Kernel logging is actually has a bunch of features.  You can turn them
on for just a module or function or enable a specific message.  See
Documentation/admin-guide/dynamic-debug-howto.rst
for more info.

This vchiq logging is a re-implementation of a subset of the features
that normal kernel logging infrastructure provides.  Moving to normal
logging will make it cleaner but also more flexible and powerful.  It's
better in every way.

The broadcom stuff is different and more complicated than what this
module is trying to do.  They are sorting out their logging according to
various components.  I understand the motivation, but they would
probably have been better just use standard logging like everyone else.

regards,
dan carpenter

Re: [RFC PATCH 0/4] Drop custom logging

[Phil Elwell]

Hi all,


On Wed, 18 Jan 2023 at 17:55, Stefan Wahren <stefan.wahren@i2se.com> wrote:
>
> Hi Umang,
>
> [add Phil]
>
> Am 18.01.23 um 12:58 schrieb Umang Jain:
> > Drop custom logging from the vchiq interface.
> > Mostly of them are replaced with dev_dbg and friends
> > and/or pr_info and friends.
> >
> > The debugfs log levels (in 4/4) are mapped to kernel
> > logs levels (coming from include/linux/kern_levels.h)
> > Would like some thoughts on it as I am not sure (hence
> > marking this is RFC)
> >
> >  From drivers/staging/vc04_services/interface/TODO:
> >
> > """
> > * Cleanup logging mechanism
> >
> > The driver should probably be using the standard kernel logging mechanisms
> > such as dev_info, dev_dbg, and friends.
>
> i don't have any experience with vchiq logging/debug. So i'm not sure if
> it's acceptable to lose the second log level dimension (like
> vchiq_arm_log_level) completely. Complex drivers like brcmfmac have a
> debug mask to avoid log spamming [1]. Maybe this is a compromise.
>
> Btw some loglevel locations has already been messed up during
> refactoring :-(
>
> [1] - drivers/net/wireless/broadcom/brcm80211/brcmfmac/debug.h
>
> > """
> >
> > Umang Jain (4):
> >    staging: vc04_services: vchiq_core: Drop custom logging
> >    staging: vc04_services: vchiq_arm: Drop custom logging
> >    staging: vc04_services: Drop custom logging
> >    staging: vc04_services: Drop remnants of custom logging
> >
> >   .../interface/vchiq_arm/vchiq_arm.c           | 151 +++---
> >   .../interface/vchiq_arm/vchiq_connected.c     |   5 +-
> >   .../interface/vchiq_arm/vchiq_core.c          | 479 ++++++++----------
> >   .../interface/vchiq_arm/vchiq_core.h          |  39 --
> >   .../interface/vchiq_arm/vchiq_debugfs.c       |  26 +-
> >   .../interface/vchiq_arm/vchiq_dev.c           |  78 ++-
> >   6 files changed, 329 insertions(+), 449 deletions(-)
> >

Thanks for the nudge - this patch set hasn't yet made its way through
the sluggish rpi-kernel moderation.

I understand the desire to remove the custom logging. I don't welcome
the loss of flexibility that comes with such a strategy, but I'm not
going to argue about it. What's harder to understand is the state that
this patchset leaves VCHIQ logging in. From what I can see, the
per-service logging control has gone, but the code still contains
macros that hint at something useful. Similarly, the debugfs support
is completely vestigial, giving the appearance of control while
actually achieving nothing.

Phil

Re: [RFC PATCH 0/4] Drop custom logging

[Greg Kroah-Hartman]

On Thu, Jan 19, 2023 at 01:31:12PM +0000, Phil Elwell wrote:
> Hi all,
> 
> 
> On Wed, 18 Jan 2023 at 17:55, Stefan Wahren <stefan.wahren@i2se.com> wrote:
> >
> > Hi Umang,
> >
> > [add Phil]
> >
> > Am 18.01.23 um 12:58 schrieb Umang Jain:
> > > Drop custom logging from the vchiq interface.
> > > Mostly of them are replaced with dev_dbg and friends
> > > and/or pr_info and friends.
> > >
> > > The debugfs log levels (in 4/4) are mapped to kernel
> > > logs levels (coming from include/linux/kern_levels.h)
> > > Would like some thoughts on it as I am not sure (hence
> > > marking this is RFC)
> > >
> > >  From drivers/staging/vc04_services/interface/TODO:
> > >
> > > """
> > > * Cleanup logging mechanism
> > >
> > > The driver should probably be using the standard kernel logging mechanisms
> > > such as dev_info, dev_dbg, and friends.
> >
> > i don't have any experience with vchiq logging/debug. So i'm not sure if
> > it's acceptable to lose the second log level dimension (like
> > vchiq_arm_log_level) completely. Complex drivers like brcmfmac have a
> > debug mask to avoid log spamming [1]. Maybe this is a compromise.
> >
> > Btw some loglevel locations has already been messed up during
> > refactoring :-(
> >
> > [1] - drivers/net/wireless/broadcom/brcm80211/brcmfmac/debug.h
> >
> > > """
> > >
> > > Umang Jain (4):
> > >    staging: vc04_services: vchiq_core: Drop custom logging
> > >    staging: vc04_services: vchiq_arm: Drop custom logging
> > >    staging: vc04_services: Drop custom logging
> > >    staging: vc04_services: Drop remnants of custom logging
> > >
> > >   .../interface/vchiq_arm/vchiq_arm.c           | 151 +++---
> > >   .../interface/vchiq_arm/vchiq_connected.c     |   5 +-
> > >   .../interface/vchiq_arm/vchiq_core.c          | 479 ++++++++----------
> > >   .../interface/vchiq_arm/vchiq_core.h          |  39 --
> > >   .../interface/vchiq_arm/vchiq_debugfs.c       |  26 +-
> > >   .../interface/vchiq_arm/vchiq_dev.c           |  78 ++-
> > >   6 files changed, 329 insertions(+), 449 deletions(-)
> > >
> 
> Thanks for the nudge - this patch set hasn't yet made its way through
> the sluggish rpi-kernel moderation.
> 
> I understand the desire to remove the custom logging. I don't welcome
> the loss of flexibility that comes with such a strategy

What "loss of flexibility"?  You now have access to the full dynamic
debugging facilities that all of the rest of the kernel has.  What is
lacking?

> , but I'm not
> going to argue about it. What's harder to understand is the state that
> this patchset leaves VCHIQ logging in. From what I can see, the
> per-service logging control has gone, but the code still contains
> macros that hint at something useful. Similarly, the debugfs support
> is completely vestigial, giving the appearance of control while
> actually achieving nothing.

The debugfs files should also be removed if they don't do anything
anymore.

thanks,

greg k-h

Re: [RFC PATCH 0/4] Drop custom logging

[Phil Elwell]

On Thu, 19 Jan 2023 at 13:37, Greg Kroah-Hartman
<gregkh@linuxfoundation.org> wrote:
>
> On Thu, Jan 19, 2023 at 01:31:12PM +0000, Phil Elwell wrote:
> > Hi all,
> >
> >
> > On Wed, 18 Jan 2023 at 17:55, Stefan Wahren <stefan.wahren@i2se.com> wrote:
> > >
> > > Hi Umang,
> > >
> > > [add Phil]
> > >
> > > Am 18.01.23 um 12:58 schrieb Umang Jain:
> > > > Drop custom logging from the vchiq interface.
> > > > Mostly of them are replaced with dev_dbg and friends
> > > > and/or pr_info and friends.
> > > >
> > > > The debugfs log levels (in 4/4) are mapped to kernel
> > > > logs levels (coming from include/linux/kern_levels.h)
> > > > Would like some thoughts on it as I am not sure (hence
> > > > marking this is RFC)
> > > >
> > > >  From drivers/staging/vc04_services/interface/TODO:
> > > >
> > > > """
> > > > * Cleanup logging mechanism
> > > >
> > > > The driver should probably be using the standard kernel logging mechanisms
> > > > such as dev_info, dev_dbg, and friends.
> > >
> > > i don't have any experience with vchiq logging/debug. So i'm not sure if
> > > it's acceptable to lose the second log level dimension (like
> > > vchiq_arm_log_level) completely. Complex drivers like brcmfmac have a
> > > debug mask to avoid log spamming [1]. Maybe this is a compromise.
> > >
> > > Btw some loglevel locations has already been messed up during
> > > refactoring :-(
> > >
> > > [1] - drivers/net/wireless/broadcom/brcm80211/brcmfmac/debug.h
> > >
> > > > """
> > > >
> > > > Umang Jain (4):
> > > >    staging: vc04_services: vchiq_core: Drop custom logging
> > > >    staging: vc04_services: vchiq_arm: Drop custom logging
> > > >    staging: vc04_services: Drop custom logging
> > > >    staging: vc04_services: Drop remnants of custom logging
> > > >
> > > >   .../interface/vchiq_arm/vchiq_arm.c           | 151 +++---
> > > >   .../interface/vchiq_arm/vchiq_connected.c     |   5 +-
> > > >   .../interface/vchiq_arm/vchiq_core.c          | 479 ++++++++----------
> > > >   .../interface/vchiq_arm/vchiq_core.h          |  39 --
> > > >   .../interface/vchiq_arm/vchiq_debugfs.c       |  26 +-
> > > >   .../interface/vchiq_arm/vchiq_dev.c           |  78 ++-
> > > >   6 files changed, 329 insertions(+), 449 deletions(-)
> > > >
> >
> > Thanks for the nudge - this patch set hasn't yet made its way through
> > the sluggish rpi-kernel moderation.
> >
> > I understand the desire to remove the custom logging. I don't welcome
> > the loss of flexibility that comes with such a strategy
>
> What "loss of flexibility"?  You now have access to the full dynamic
> debugging facilities that all of the rest of the kernel has.  What is
> lacking?

Perhaps I've missed something, either in this patch set or the kernel
as a whole, but how is one supposed to set different logging levels on
different facilities within a driver/module, or even for the module as
a whole? I don't consider anything that requires reference to
individual lines in the source code to be a suitable replacement,
clever though it is.

> > , but I'm not
> > going to argue about it. What's harder to understand is the state that
> > this patchset leaves VCHIQ logging in. From what I can see, the
> > per-service logging control has gone, but the code still contains
> > macros that hint at something useful. Similarly, the debugfs support
> > is completely vestigial, giving the appearance of control while
> > actually achieving nothing.
>
> The debugfs files should also be removed if they don't do anything
> anymore.
>
> thanks,
>
> greg k-h

Re: [RFC PATCH 0/4] Drop custom logging

[Dan Carpenter]

On Thu, Jan 19, 2023 at 01:47:44PM +0000, Phil Elwell wrote:
> > > I understand the desire to remove the custom logging. I don't welcome
> > > the loss of flexibility that comes with such a strategy
> >
> > What "loss of flexibility"?  You now have access to the full dynamic
> > debugging facilities that all of the rest of the kernel has.  What is
> > lacking?
> 
> Perhaps I've missed something, either in this patch set or the kernel
> as a whole, but how is one supposed to set different logging levels on
> different facilities within a driver/module, or even for the module as
> a whole?

Yeah.  You will be still able to do that and more besides after the
transition.  Cleaning this up makes the code better in every way.

Documentation/admin-guide/dynamic-debug-howto.rst

regards,
dan carpenter

Re: [RFC PATCH 0/4] Drop custom logging

[Phil Elwell]

On Thu, 19 Jan 2023 at 14:25, Dan Carpenter <error27@gmail.com> wrote:
>
> On Thu, Jan 19, 2023 at 01:47:44PM +0000, Phil Elwell wrote:
> > > > I understand the desire to remove the custom logging. I don't welcome
> > > > the loss of flexibility that comes with such a strategy
> > >
> > > What "loss of flexibility"?  You now have access to the full dynamic
> > > debugging facilities that all of the rest of the kernel has.  What is
> > > lacking?
> >
> > Perhaps I've missed something, either in this patch set or the kernel
> > as a whole, but how is one supposed to set different logging levels on
> > different facilities within a driver/module, or even for the module as
> > a whole?
>
> Yeah.  You will be still able to do that and more besides after the
> transition.  Cleaning this up makes the code better in every way.
>
> Documentation/admin-guide/dynamic-debug-howto.rst

Are you saying this patch set gets us to that point?

Re: [RFC PATCH 0/4] Drop custom logging

[Dan Carpenter]

On Thu, Jan 19, 2023 at 02:31:50PM +0000, Phil Elwell wrote:
> On Thu, 19 Jan 2023 at 14:25, Dan Carpenter <error27@gmail.com> wrote:
> >
> > On Thu, Jan 19, 2023 at 01:47:44PM +0000, Phil Elwell wrote:
> > > > > I understand the desire to remove the custom logging. I don't welcome
> > > > > the loss of flexibility that comes with such a strategy
> > > >
> > > > What "loss of flexibility"?  You now have access to the full dynamic
> > > > debugging facilities that all of the rest of the kernel has.  What is
> > > > lacking?
> > >
> > > Perhaps I've missed something, either in this patch set or the kernel
> > > as a whole, but how is one supposed to set different logging levels on
> > > different facilities within a driver/module, or even for the module as
> > > a whole?
> >
> > Yeah.  You will be still able to do that and more besides after the
> > transition.  Cleaning this up makes the code better in every way.
> >
> > Documentation/admin-guide/dynamic-debug-howto.rst
> 
> Are you saying this patch set gets us to that point?

Yes.  The patch has some issues, but yes.

regards,
dan carpenter

Re: [RFC PATCH 0/4] Drop custom logging

[Phil Elwell]

On Thu, 19 Jan 2023 at 14:37, Dan Carpenter <error27@gmail.com> wrote:
>
> On Thu, Jan 19, 2023 at 02:31:50PM +0000, Phil Elwell wrote:
> > On Thu, 19 Jan 2023 at 14:25, Dan Carpenter <error27@gmail.com> wrote:
> > >
> > > On Thu, Jan 19, 2023 at 01:47:44PM +0000, Phil Elwell wrote:
> > > > > > I understand the desire to remove the custom logging. I don't welcome
> > > > > > the loss of flexibility that comes with such a strategy
> > > > >
> > > > > What "loss of flexibility"?  You now have access to the full dynamic
> > > > > debugging facilities that all of the rest of the kernel has.  What is
> > > > > lacking?
> > > >
> > > > Perhaps I've missed something, either in this patch set or the kernel
> > > > as a whole, but how is one supposed to set different logging levels on
> > > > different facilities within a driver/module, or even for the module as
> > > > a whole?
> > >
> > > Yeah.  You will be still able to do that and more besides after the
> > > transition.  Cleaning this up makes the code better in every way.
> > >
> > > Documentation/admin-guide/dynamic-debug-howto.rst
> >
> > Are you saying this patch set gets us to that point?
>
> Yes.  The patch has some issues, but yes.

OK, thanks. I'll be watching how this plays out with interest.

Phil

Re: [RFC PATCH 0/4] Drop custom logging

[Laurent Pinchart]

On Thu, Jan 19, 2023 at 05:37:48PM +0300, Dan Carpenter wrote:
> On Thu, Jan 19, 2023 at 02:31:50PM +0000, Phil Elwell wrote:
> > On Thu, 19 Jan 2023 at 14:25, Dan Carpenter wrote:
> > > On Thu, Jan 19, 2023 at 01:47:44PM +0000, Phil Elwell wrote:
> > > > > > I understand the desire to remove the custom logging. I don't welcome
> > > > > > the loss of flexibility that comes with such a strategy
> > > > >
> > > > > What "loss of flexibility"?  You now have access to the full dynamic
> > > > > debugging facilities that all of the rest of the kernel has.  What is
> > > > > lacking?
> > > >
> > > > Perhaps I've missed something, either in this patch set or the kernel
> > > > as a whole, but how is one supposed to set different logging levels on
> > > > different facilities within a driver/module, or even for the module as
> > > > a whole?
> > >
> > > Yeah.  You will be still able to do that and more besides after the
> > > transition.  Cleaning this up makes the code better in every way.
> > >
> > > Documentation/admin-guide/dynamic-debug-howto.rst
> > 
> > Are you saying this patch set gets us to that point?
> 
> Yes.  The patch has some issues, but yes.

I think I'm missing something too then. Dynamic debug provides the
ability to easily switch dev_dbg() messages on and off at runtime, but
it doesn't provide, as far as I'm aware, log levels or log categories.

Log levels are currently used by the vchiq code to suppress messages
below a certain level. Kernel log levels are not an exact replacement,
as the messages still end up in the kernel log (except for debug
messages).

Log categories are used to group messages in categories and control
their log level per category. As far as I know, dynamic debug doesn't
provide any such feature.

-- 
Regards,

Laurent Pinchart

Re: [RFC PATCH 0/4] Drop custom logging

[Laurent Pinchart]

On Fri, Jan 20, 2023 at 02:53:17AM +0200, Laurent Pinchart wrote:
> On Thu, Jan 19, 2023 at 05:37:48PM +0300, Dan Carpenter wrote:
> > On Thu, Jan 19, 2023 at 02:31:50PM +0000, Phil Elwell wrote:
> > > On Thu, 19 Jan 2023 at 14:25, Dan Carpenter wrote:
> > > > On Thu, Jan 19, 2023 at 01:47:44PM +0000, Phil Elwell wrote:
> > > > > > > I understand the desire to remove the custom logging. I don't welcome
> > > > > > > the loss of flexibility that comes with such a strategy
> > > > > >
> > > > > > What "loss of flexibility"?  You now have access to the full dynamic
> > > > > > debugging facilities that all of the rest of the kernel has.  What is
> > > > > > lacking?
> > > > >
> > > > > Perhaps I've missed something, either in this patch set or the kernel
> > > > > as a whole, but how is one supposed to set different logging levels on
> > > > > different facilities within a driver/module, or even for the module as
> > > > > a whole?
> > > >
> > > > Yeah.  You will be still able to do that and more besides after the
> > > > transition.  Cleaning this up makes the code better in every way.
> > > >
> > > > Documentation/admin-guide/dynamic-debug-howto.rst
> > > 
> > > Are you saying this patch set gets us to that point?
> > 
> > Yes.  The patch has some issues, but yes.
> 
> I think I'm missing something too then. Dynamic debug provides the
> ability to easily switch dev_dbg() messages on and off at runtime, but
> it doesn't provide, as far as I'm aware, log levels or log categories.
> 
> Log levels are currently used by the vchiq code to suppress messages
> below a certain level. Kernel log levels are not an exact replacement,
> as the messages still end up in the kernel log (except for debug
> messages).
> 
> Log categories are used to group messages in categories and control
> their log level per category. As far as I know, dynamic debug doesn't
> provide any such feature.

After a bit more research (which I should have done before replying,
sorry), it looks like dynamic debug has support for classes, which are
used by, for instance, the DRM logging infrastructure (see
include/drm/drm_print.h). I don't see that being wired up to dev_*()
print macros though, am I missing something, or would vchiq need to keep
using custom logging macros (with dynamic debug used as a backend,
replacing the current custom implementation) to make use of this feature
?

-- 
Regards,

Laurent Pinchart

Re: [RFC PATCH 0/4] Drop custom logging

[Dan Carpenter]

On Fri, Jan 20, 2023 at 02:53:15AM +0200, Laurent Pinchart wrote:
> Log categories are used to group messages in categories and control
> their log level per category. As far as I know, dynamic debug doesn't
> provide any such feature.

One idea is you could put the category in the format string.  Then you
could just grep /proc/dynamic_debug/control for it and enable the printks
like that.

regards,
dan carpenter

Re: [RFC PATCH 0/4] Drop custom logging

[Greg Kroah-Hartman]

On Wed, Jan 18, 2023 at 05:28:06PM +0530, Umang Jain wrote:
> Drop custom logging from the vchiq interface.
> Mostly of them are replaced with dev_dbg and friends
> and/or pr_info and friends. 

Everything should be dev_*() calls, there should never be a pr_* call in
a driver.

> The debugfs log levels (in 4/4) are mapped to kernel
> logs levels (coming from include/linux/kern_levels.h)
> Would like some thoughts on it as I am not sure (hence
> marking this is RFC)

Do not have any "custom" debugging controls in a driver, they are not
special and should follow the whole rest of the kernel.  Just remove
them all and rely on the existing dev_*() calls instead please.

thanks,

greg k-h

Re: [RFC PATCH 0/4] Drop custom logging

[Stefan Wahren]

Hi Umang,

Am 18.01.23 um 12:58 schrieb Umang Jain:
> Drop custom logging from the vchiq interface.
> Mostly of them are replaced with dev_dbg and friends
> and/or pr_info and friends.
>
> The debugfs log levels (in 4/4) are mapped to kernel
> logs levels (coming from include/linux/kern_levels.h)
> Would like some thoughts on it as I am not sure (hence
> marking this is RFC)
>
>  From drivers/staging/vc04_services/interface/TODO:
>
> """
> * Cleanup logging mechanism
>
> The driver should probably be using the standard kernel logging mechanisms
> such as dev_info, dev_dbg, and friends.
> """

at first i want to thank you for the work on vchiq so far.

There is something which is not directly related to this series, but it 
is also about debugging. The driver has a buffer which is accessed by 
it's own DEBUG_* macros. The content of this debug buffer can be dumped 
via the /dev/vchiq which is also used by ioctl. I would appreciate to 
move this dump feature into a new debugfs entry.

Best regards

Re: [RFC PATCH 0/4] Drop custom logging

[Kieran Bingham]

Hi Stefan,

Quoting Stefan Wahren (2023-01-22 14:21:05)
> Hi Umang,
> 
> Am 18.01.23 um 12:58 schrieb Umang Jain:
> > Drop custom logging from the vchiq interface.
> > Mostly of them are replaced with dev_dbg and friends
> > and/or pr_info and friends.
> >
> > The debugfs log levels (in 4/4) are mapped to kernel
> > logs levels (coming from include/linux/kern_levels.h)
> > Would like some thoughts on it as I am not sure (hence
> > marking this is RFC)
> >
> >  From drivers/staging/vc04_services/interface/TODO:
> >
> > """
> > * Cleanup logging mechanism
> >
> > The driver should probably be using the standard kernel logging mechanisms
> > such as dev_info, dev_dbg, and friends.
> > """
> 
> at first i want to thank you for the work on vchiq so far.
> 
> There is something which is not directly related to this series, but it 
> is also about debugging. The driver has a buffer which is accessed by 
> it's own DEBUG_* macros. The content of this debug buffer can be dumped 
> via the /dev/vchiq which is also used by ioctl. I would appreciate to 
> move this dump feature into a new debugfs entry.

Do you have a full list of the tasks you'd like to see completed ?
(including/or above drivers/staging/vc04_services/interface/TODO)

It would help to have a clear picture of tasks needed to get this driver
destaged, so that we can support the ISP upstream.

Regards
--
Kieran

Re: [RFC PATCH 0/4] Drop custom logging

[Stefan Wahren]

Hi Kieran,

Am 22.01.23 um 17:26 schrieb Kieran Bingham:
> Hi Stefan,
>
> Quoting Stefan Wahren (2023-01-22 14:21:05)
>> Hi Umang,
>>
>> Am 18.01.23 um 12:58 schrieb Umang Jain:
>>> Drop custom logging from the vchiq interface.
>>> Mostly of them are replaced with dev_dbg and friends
>>> and/or pr_info and friends.
>>>
>>> The debugfs log levels (in 4/4) are mapped to kernel
>>> logs levels (coming from include/linux/kern_levels.h)
>>> Would like some thoughts on it as I am not sure (hence
>>> marking this is RFC)
>>>
>>>   From drivers/staging/vc04_services/interface/TODO:
>>>
>>> """
>>> * Cleanup logging mechanism
>>>
>>> The driver should probably be using the standard kernel logging mechanisms
>>> such as dev_info, dev_dbg, and friends.
>>> """
>> at first i want to thank you for the work on vchiq so far.
>>
>> There is something which is not directly related to this series, but it
>> is also about debugging. The driver has a buffer which is accessed by
>> it's own DEBUG_* macros. The content of this debug buffer can be dumped
>> via the /dev/vchiq which is also used by ioctl. I would appreciate to
>> move this dump feature into a new debugfs entry.
> Do you have a full list of the tasks you'd like to see completed ?
> (including/or above drivers/staging/vc04_services/interface/TODO)

i consider every point except of point 1 (importing new drivers) as 
necessary to leave staging.

Additionally there is the additional point (i can add them to the TODO) 
above. Unfortunately i don't have a complete insight, how vchiq should 
be to be acceptable. Sorry, if i can't help you further with possible 
resource planning.

Are some points on the TODO list unclear?

Thanks

>
> It would help to have a clear picture of tasks needed to get this driver
> destaged, so that we can support the ISP upstream.
>
> Regards
> --
> Kieran

Re: [RFC PATCH 0/4] Drop custom logging

[Kieran Bingham]

Hi Stefan,

Quoting Stefan Wahren (2023-01-22 18:07:03)
> Hi Kieran,
> 
> Am 22.01.23 um 17:26 schrieb Kieran Bingham:
> > Hi Stefan,
> >
> > Quoting Stefan Wahren (2023-01-22 14:21:05)
> >> Hi Umang,
> >>
> >> Am 18.01.23 um 12:58 schrieb Umang Jain:
> >>> Drop custom logging from the vchiq interface.
> >>> Mostly of them are replaced with dev_dbg and friends
> >>> and/or pr_info and friends.
> >>>
> >>> The debugfs log levels (in 4/4) are mapped to kernel
> >>> logs levels (coming from include/linux/kern_levels.h)
> >>> Would like some thoughts on it as I am not sure (hence
> >>> marking this is RFC)
> >>>
> >>>   From drivers/staging/vc04_services/interface/TODO:
> >>>
> >>> """
> >>> * Cleanup logging mechanism
> >>>
> >>> The driver should probably be using the standard kernel logging mechanisms
> >>> such as dev_info, dev_dbg, and friends.
> >>> """
> >> at first i want to thank you for the work on vchiq so far.
> >>
> >> There is something which is not directly related to this series, but it
> >> is also about debugging. The driver has a buffer which is accessed by
> >> it's own DEBUG_* macros. The content of this debug buffer can be dumped
> >> via the /dev/vchiq which is also used by ioctl. I would appreciate to
> >> move this dump feature into a new debugfs entry.
> > Do you have a full list of the tasks you'd like to see completed ?
> > (including/or above drivers/staging/vc04_services/interface/TODO)
> 
> i consider every point except of point 1 (importing new drivers) as 
> necessary to leave staging.

Thanks

> Additionally there is the additional point (i can add them to the TODO) 
> above. Unfortunately i don't have a complete insight, how vchiq should 
> be to be acceptable. Sorry, if i can't help you further with possible 
> resource planning.
> 
> Are some points on the TODO list unclear?

I believe the list is fine, but I was enquiring if there were anymore
additional tasks above the scope listed in
drivers/staging/vc04_services/interface/TODO which are required. I don't
think you need to send a patch for the task above - unless there are a
lot more tasks required, or it becomes too much to do now.

The goal is to get the ISP upstream to support libcamera, and it would
help to know how deep the rabbit hole really is ;-)

--
Kieran