log: add function name, line number prefix

Use do-while(0) to define the metal_log macro. Add convenience macros
ml_err, ml_warn, ml_info, ml_dbg to avoid using excessively long and
redundant "metal_log(METAL_LOG_*". Add "function-name:line-number"
prefix to all messages if the option WITH_FUNC_LINE_LOG is set ON
during the configuration phase.

Signed-off-by: Sergei Korneichuk <sergei.korneichuk@amd.com>

cmake/options.cmake

@@ -69,6 +69,7 @@ if (WITH_ZEPHYR)
 endif (WITH_ZEPHYR)
 
 option (WITH_DEFAULT_LOGGER "Build with default logger" ON)
+option (WITH_FUNC_LINE_LOG "Log with function name, line number prefix" OFF)
 
 option (WITH_DOC "Build with documentation" ON)
 

lib/CMakeLists.txt

@@ -65,6 +65,10 @@ if (WITH_DEFAULT_LOGGER)
   add_definitions (-DDEFAULT_LOGGER_ON)
 endif (WITH_DEFAULT_LOGGER)
 
+if (WITH_FUNC_LINE_LOG)
+  add_definitions (-DML_FUNC_LINE)
+endif (WITH_FUNC_LINE_LOG)
+
 get_property (_ec_flgs GLOBAL PROPERTY "PROJECT_EC_FLAGS")
 
 if (WITH_ZEPHYR)

lib/device.c

@@ -23,7 +23,7 @@ int metal_bus_register(struct metal_bus *bus)
 		return -EEXIST;
 	metal_list_init(&bus->devices);
 	metal_list_add_tail(&_metal.common.bus_list, &bus->node);
-	metal_log(METAL_LOG_DEBUG, "registered %s bus\n", bus->name);
+	ml_dbg("registered %s bus\n", bus->name);
 	return 0;
 }
 
@@ -32,7 +32,7 @@ int metal_bus_unregister(struct metal_bus *bus)
 	metal_list_del(&bus->node);
 	if (bus->ops.bus_close)
 		bus->ops.bus_close(bus);
-	metal_log(METAL_LOG_DEBUG, "unregistered %s bus\n", bus->name);
+	ml_dbg("unregistered %s bus\n", bus->name);
 	return 0;
 }
 

lib/log.h

@@ -71,16 +71,36 @@ extern enum metal_log_level metal_get_log_level(void);
 extern void metal_default_log_handler(enum metal_log_level level,
 				      const char *format, ...);
 
+/**
+ * @brief	used by the metal_log() macro to update the format string
+ * @fmt	format string passed from the metal_log() macro
+ *
+ * If ML_FUNC_LINE is defined this macro generates a unified format
+ * string for metal_log() and its convenience ml_*() macros, i.e. it
+ * adds function-name:line-number prefix to all log messages.
+ */
+#if defined(ML_FUNC_LINE)
+#define ml_fmt(fmt) "%s:%u " fmt, __func__, __LINE__
+#else	/* ML_FUNC_LINE */
+#define ml_fmt(fmt) fmt
+#endif	/* ML_FUNC_LINE */
+
 /**
  * Emit a log message if the log level permits.
  *
  * @param	level	Log level.
  * @param	...	Format string and arguments.
  */
-#define metal_log(level, ...)						       \
-	((level <= _metal.common.log_level && _metal.common.log_handler) \
-	       ? (void)_metal.common.log_handler(level, __VA_ARGS__)	       \
-	       : (void)0)
+#define metal_log(level, fmt, args ...)					\
+do {									\
+	if (_metal.common.log_handler && level <= _metal.common.log_level) \
+		_metal.common.log_handler(level, ml_fmt(fmt), ##args);	\
+} while (0)
+
+#define ml_err(fmt, args ...) metal_log(METAL_LOG_ERROR, fmt, ##args)
+#define ml_warn(fmt, args ...) metal_log(METAL_LOG_WARNING, fmt, ##args)
+#define ml_info(fmt, args ...) metal_log(METAL_LOG_INFO, fmt, ##args)
+#define ml_dbg(fmt, args ...) metal_log(METAL_LOG_DEBUG, fmt, ##args)
 
 /** @} */
 

lib/softirq.c

@@ -72,8 +72,7 @@ int metal_softirq_allocate(int num)
 	int irq_base;
 
 	if ((metal_softirq_avail + num) >= metal_softirq_num) {
-		metal_log(METAL_LOG_ERROR, "No %d available soft irqs.\r\n",
-			  num);
+		ml_err("No %d available soft irqs.\r\n", num);
 		return -EINVAL;
 	}
 	irq_base = metal_softirq_avail;

lib/system/freertos/xlnx_common/irq.c

@@ -27,8 +27,7 @@ static void metal_xlnx_irq_set_enable(struct metal_irq_controller *irq_cntr,
 {
 	if (irq < irq_cntr->irq_base ||
 	    irq >= irq_cntr->irq_base + irq_cntr->irq_num) {
-		metal_log(METAL_LOG_ERROR, "%s: invalid irq %d\n",
-			  __func__, irq);
+		ml_err("%s: invalid irq %d\n", __func__, irq);
 		return;
 	} else if (state == METAL_IRQ_ENABLE) {
 		sys_irq_enable((unsigned int)irq);
@@ -64,8 +63,7 @@ int metal_xlnx_irq_init(void)
 
 	ret =  metal_irq_register_controller(&xlnx_irq_cntr);
 	if (ret < 0) {
-		metal_log(METAL_LOG_ERROR, "%s: register irq controller failed.\n",
-			  __func__);
+		ml_err("%s: register irq controller failed.\n", __func__);
 		return ret;
 	}
 	return 0;

lib/system/generic/xlnx_common/irq.c

@@ -27,8 +27,7 @@ static void metal_xlnx_irq_set_enable(struct metal_irq_controller *irq_cntr,
 {
 	if (irq < irq_cntr->irq_base ||
 	    irq >= irq_cntr->irq_base + irq_cntr->irq_num) {
-		metal_log(METAL_LOG_ERROR, "%s: invalid irq %d\n",
-			  __func__, irq);
+		ml_err("%s: invalid irq %d\n", __func__, irq);
 		return;
 	} else if (state == METAL_IRQ_ENABLE) {
 		sys_irq_enable((unsigned int)irq);
@@ -64,8 +63,7 @@ int metal_xlnx_irq_init(void)
 
 	ret =  metal_irq_register_controller(&xlnx_irq_cntr);
 	if (ret < 0) {
-		metal_log(METAL_LOG_ERROR, "%s: register irq controller failed.\n",
-			  __func__);
+		ml_err("%s: register irq controller failed.\n", __func__);
 		return ret;
 	}
 	return 0;

lib/system/linux/device.c

@@ -108,43 +108,40 @@ static int metal_uio_dev_bind(struct linux_device *ldev,
 		return 0;
 
 	if (strcmp(ldev->sdev->driver_name, SYSFS_UNKNOWN) != 0) {
-		metal_log(METAL_LOG_INFO, "device %s in use by driver %s\n",
-			  ldev->dev_name, ldev->sdev->driver_name);
+		ml_info("device %s in use by driver %s\n",
+			ldev->dev_name, ldev->sdev->driver_name);
 		return -EBUSY;
 	}
 
 	attr = sysfs_get_device_attr(ldev->sdev, "driver_override");
 	if (!attr) {
-		metal_log(METAL_LOG_ERROR, "device %s has no override\n",
-			  ldev->dev_name);
+		ml_err("device %s has no override\n", ldev->dev_name);
 		return -errno;
 	}
 
 	result = sysfs_write_attribute(attr, ldrv->drv_name,
 				       strlen(ldrv->drv_name));
 	if (result) {
-		metal_log(METAL_LOG_ERROR, "failed to set override on %s\n",
-			  ldev->dev_name);
+		ml_err("failed to set override on %s\n", ldev->dev_name);
 		return -errno;
 	}
 	ldev->override = attr;
 
 	attr = sysfs_get_driver_attr(ldrv->sdrv, "bind");
 	if (!attr) {
-		metal_log(METAL_LOG_ERROR, "driver %s has no bind\n", ldrv->drv_name);
+		ml_err("driver %s has no bind\n", ldrv->drv_name);
 		return -ENOTSUP;
 	}
 
 	result = sysfs_write_attribute(attr, ldev->dev_name,
 				       strlen(ldev->dev_name));
 	if (result) {
-		metal_log(METAL_LOG_ERROR, "failed to bind %s to %s\n",
-			  ldev->dev_name, ldrv->drv_name);
+		ml_err("failed to bind %s to %s\n",
+		       ldev->dev_name, ldrv->drv_name);
 		return -errno;
 	}
 
-	metal_log(METAL_LOG_DEBUG, "bound device %s to driver %s\n",
-		  ldev->dev_name, ldrv->drv_name);
+	ml_dbg("bound device %s to driver %s\n", ldev->dev_name, ldrv->drv_name);
 
 	return 0;
 }
@@ -160,18 +157,16 @@ static int metal_uio_dev_open(struct linux_bus *lbus, struct linux_device *ldev)
 	void *virt;
 	int irq_info;
 
-
 	ldev->fd = -1;
 	ldev->device.irq_info = (void *)-1;
 
 	ldev->sdev = sysfs_open_device(lbus->bus_name, ldev->dev_name);
 	if (!ldev->sdev) {
-		metal_log(METAL_LOG_ERROR, "device %s:%s not found\n",
-			  lbus->bus_name, ldev->dev_name);
+		ml_err("device %s:%s not found\n",
+		       lbus->bus_name, ldev->dev_name);
 		return -ENODEV;
 	}
-	metal_log(METAL_LOG_DEBUG, "opened sysfs device %s:%s\n",
-		  lbus->bus_name, ldev->dev_name);
+	ml_dbg("opened sysfs device %s:%s\n", lbus->bus_name, ldev->dev_name);
 
 	result = metal_uio_dev_bind(ldev, ldrv);
 	if (result)
@@ -182,8 +177,7 @@ static int metal_uio_dev_open(struct linux_bus *lbus, struct linux_device *ldev)
 		return -EOVERFLOW;
 	dlist = sysfs_open_directory_list(path);
 	if (!dlist) {
-		metal_log(METAL_LOG_ERROR, "failed to scan class path %s\n",
-			  path);
+		ml_err("failed to scan class path %s\n", path);
 		return -errno;
 	}
 
@@ -201,8 +195,7 @@ static int metal_uio_dev_open(struct linux_bus *lbus, struct linux_device *ldev)
 	sysfs_close_list(dlist);
 
 	if (sysfs_path_is_dir(ldev->cls_path) != 0) {
-		metal_log(METAL_LOG_ERROR, "invalid device class path %s\n",
-			  ldev->cls_path);
+		ml_err("invalid device class path %s\n", ldev->cls_path);
 		return -ENODEV;
 	}
 
@@ -214,20 +207,19 @@ static int metal_uio_dev_open(struct linux_bus *lbus, struct linux_device *ldev)
 		i++;
 	} while (i < 1000);
 	if (i >= 1000) {
-		metal_log(METAL_LOG_ERROR, "failed to open file %s, timeout.\n",
-			  ldev->dev_path);
+		ml_err("failed to open file %s, timeout.\n", ldev->dev_path);
 		return -ENODEV;
 	}
 	result = metal_open(ldev->dev_path, 0);
 	if (result < 0) {
-		metal_log(METAL_LOG_ERROR, "failed to open device %s\n",
-			  ldev->dev_path, strerror(-result));
+		ml_err("failed to open device %s\n",
+		       ldev->dev_path, strerror(-result));
 		return result;
 	}
 	ldev->fd = result;
 
-	metal_log(METAL_LOG_DEBUG, "opened %s:%s as %s\n",
-		  lbus->bus_name, ldev->dev_name, ldev->dev_path);
+	ml_dbg("opened %s:%s as %s\n",
+	       lbus->bus_name, ldev->dev_name, ldev->dev_path);
 
 	for (i = 0, result = 0; !result && i < METAL_MAX_DEVICE_REGIONS; i++) {
 		phys = &ldev->region_phys[ldev->device.num_regions];
@@ -248,9 +240,7 @@ static int metal_uio_dev_open(struct linux_bus *lbus, struct linux_device *ldev)
 
 	irq_info = 1;
 	if (write(ldev->fd, &irq_info, sizeof(irq_info)) <= 0) {
-		metal_log(METAL_LOG_INFO,
-			  "%s: No IRQ for device %s.\n",
-			  __func__, ldev->dev_name);
+		ml_info("%s: No IRQ for device %s\n", __func__, ldev->dev_name);
 		ldev->device.irq_num =  0;
 		ldev->device.irq_info = (void *)-1;
 	} else {
@@ -297,14 +287,14 @@ static void metal_uio_dev_irq_ack(struct linux_bus *lbus,
 
 	ret = read(ldev->fd, (void *)&val, sizeof(val));
 	if (ret < 0) {
-		metal_log(METAL_LOG_ERROR, "%s, read uio irq fd %d failed: %d.\n",
-						__func__, ldev->fd, ret);
+		ml_err("%s, read uio irq fd %d failed: %d.\n",
+		       __func__, ldev->fd, ret);
 		return;
 	}
 	ret = write(ldev->fd, &irq_info, sizeof(irq_info));
 	if (ret < 0) {
-		metal_log(METAL_LOG_ERROR, "%s, write uio irq fd %d failed: %d.\n",
-						__func__, ldev->fd, errno);
+		ml_err("%s, write uio irq fd %d failed: %d.\n",
+		       __func__, ldev->fd, errno);
 	}
 }
 
@@ -336,9 +326,9 @@ static int metal_uio_dev_dma_map(struct linux_bus *lbus,
 			}
 		}
 		if (j == (int)ldev->device.num_regions) {
-			metal_log(METAL_LOG_WARNING,
-			  "%s,%s: input address isn't MMIO addr: 0x%x,%d.\n",
-			__func__, ldev->dev_name, vaddr_sg_lo, sg_in[i].len);
+			ml_warn("%s,%s: input addr isn't MMIO addr: 0x%x,%d\n",
+				__func__,
+				ldev->dev_name, vaddr_sg_lo, sg_in[i].len);
 			return -EINVAL;
 		}
 	}
@@ -566,9 +556,7 @@ static int metal_linux_probe_driver(struct linux_bus *lbus,
 			return -EOVERFLOW;
 		ret = system(command);
 		if (ret < 0) {
-			metal_log(METAL_LOG_WARNING,
-				  "%s: executing system command '%s' failed.\n",
-				  __func__, command);
+			ml_warn("system('%s') failed.\n", command);
 		}
 		ldrv->sdrv = sysfs_open_driver(lbus->bus_name, ldrv->drv_name);
 	}
@@ -581,9 +569,7 @@ static int metal_linux_probe_driver(struct linux_bus *lbus,
 			return -EOVERFLOW;
 		ret = system(command);
 		if (ret < 0) {
-			metal_log(METAL_LOG_WARNING,
-				  "%s: executing system command '%s' failed.\n",
-				  __func__, command);
+			ml_warn("system('%s') failed.\n", command);
 		}
 		ldrv->sdrv = sysfs_open_driver(lbus->bus_name, ldrv->drv_name);
 	}

lib/system/linux/init.c

@@ -34,14 +34,12 @@ static int metal_add_page_size(const char *path, int shift, int mmap_flags)
 	unsigned long size = 1UL << shift;
 
 	if (index >= MAX_PAGE_SIZES) {
-		metal_log(METAL_LOG_WARNING, "skipped page size %ld - overflow\n",
-			  size);
+		ml_warn("skipped page size %ld - overflow\n", size);
 		return -EOVERFLOW;
 	}
 
 	if (!path || shift <= 0) {
-		metal_log(METAL_LOG_WARNING, "skipped page size %ld - invalid args\n",
-			  size);
+		ml_warn("skipped page size %ld - invalid args\n", size);
 		return -EINVAL;
 	}
 
@@ -51,7 +49,7 @@ static int metal_add_page_size(const char *path, int shift, int mmap_flags)
 	strncpy(_metal.page_sizes[index].path, path, PATH_MAX);
 	_metal.num_page_sizes++;
 
-	metal_log(METAL_LOG_DEBUG, "added page size %ld @%s\n", size, path);
+	ml_dbg("added page size %ld @%s\n", size, path);
 
 	return 0;
 }
@@ -64,7 +62,7 @@ static int metal_init_page_sizes(void)
 	/* Determine system page size. */
 	sizes[0] = getpagesize();
 	if (sizes[0] <= 0) {
-		metal_log(METAL_LOG_ERROR, "failed to get page size\n");
+		ml_err("failed to get page size\n");
 		return -ENOSYS;
 	}
 	_metal.page_size  = sizes[0];
@@ -118,8 +116,7 @@ int metal_sys_init(const struct metal_init_params *params)
 	/* Determine sysfs mount point. */
 	result = sysfs_get_mnt_path(sysfs_path, sizeof(sysfs_path));
 	if (result) {
-		metal_log(METAL_LOG_ERROR, "failed to get sysfs path (%s)\n",
-			  strerror(-result));
+		ml_err("failed to get sysfs path (%s)\n", strerror(-result));
 		return result;
 	}
 	_metal.sysfs_path = sysfs_path;
@@ -133,12 +130,11 @@ int metal_sys_init(const struct metal_init_params *params)
 	/* Initialize the pseudo-random number generator. */
 	urandom = fopen("/dev/urandom", "r");
 	if (!urandom) {
-		metal_log(METAL_LOG_ERROR, "failed to open /dev/urandom (%s)\n",
-			  strerror(errno));
+		ml_err("failed to open /dev/urandom (%s)\n", strerror(errno));
 		return -errno;
 	}
 	if (fread(&seed, 1, sizeof(seed), urandom) <= 0) {
-		metal_log(METAL_LOG_DEBUG, "Failed fread /dev/urandom\n");
+		ml_dbg("Failed fread /dev/urandom\n");
 	}
 	fclose(urandom);
 	srand(seed);
@@ -153,8 +149,7 @@ int metal_sys_init(const struct metal_init_params *params)
 
 	result = open("/proc/self/pagemap", O_RDONLY | O_CLOEXEC);
 	if (result < 0) {
-		metal_log(METAL_LOG_DEBUG, "Failed pagemap open - %s\n",
-			  strerror(errno));
+		ml_dbg("Failed pagemap open - %s\n", strerror(errno));
 	}
 	_metal.pagemap_fd = result;