ANDROID: trusty-log: Complement logging sink with unthrottled virtual file

Add a secondary unthrottled sink to trusty logging,
via a new virtual file (/dev/logbuffer_trusty)

Bug: 188285071
Change-Id: I6236beffc3070dde2fd471449f29a7556cf749ef
Signed-off-by: Armelle Laine <armellel@google.com>

1 files changed, 283 insertions, 7 deletions

diff --git a/drivers/trusty/trusty-log.c b/drivers/trusty/trusty-log.c
index 87982db..315e482 100644
--- a/drivers/trusty/trusty-log.c
+++ b/drivers/trusty/trusty-log.c
@@ -12,6 +12,8 @@
 #include <linux/mod_devicetable.h>
 #include <linux/module.h>
 #include <linux/log2.h>
+#include <linux/miscdevice.h>
+#include <linux/seq_file.h>
 #include <asm/page.h>
 #include "trusty-log.h"
 
@@ -38,26 +40,53 @@ static struct ratelimit_state trusty_log_rate_limit =
 	RATELIMIT_STATE_INIT("trusty_log", 1 * HZ, 100);
 
 /**
+ * struct trusty_log_sfile - trusty log misc device state
+ *
+ * @misc:          misc device created for the trusty log virtual file
+ * @sfile:         seq_file created when opening the misc device
+ * @device_name:   misc device name following the convention
+ *                 "trusty-<name><id>"
+ */
+struct trusty_log_sfile {
+	struct miscdevice misc;
+	struct seq_file sfile;
+	char device_name[64];
+};
+
+/**
  * struct trusty_log_sink_state - trusty log sink state
  *
  * @get:              current read unwrapped index
  * @last_successful_next:
  *                    index for the next line after the last successful get
  * @trusty_panicked:  trusty panic status at the start of the sink interation
+ *                    (only used for kernel log sink)
+ * @sfile:            seq_file used for sinking to a virtual file (misc device);
+ *                    set to NULL for the kernel log sink.
+ * @ignore_overflow:  ignore_overflow used to coalesce overflow messages and
+ *                    avoid reporting an overflow when sinking the oldest
+ *                    line to the virtual file (only used for virtual file sink)
  *
- * A sink state structure is used for each log sink (e.g. the kernel log sink
- * and later virtual file sinks).
+ * A sink state structure is used for both the kernel log sink
+ * and the virtual device sink.
+ * An instance of the sink state structure is dynamically created
+ * for each read iteration of the trusty log virtual file (misc device).
  *
  */
 struct trusty_log_sink_state {
 	u32 get;
 	u32 last_successful_next;
 	bool trusty_panicked;
+
+	/* virtual file sink specific attributes */
+	struct seq_file *sfile;
+	bool ignore_overflow;
 };
 
 struct trusty_log_state {
 	struct device *dev;
 	struct device *trusty_dev;
+	struct trusty_log_sfile log_sfile;
 
 	/*
 	 * This lock is here to ensure only one consumer will read
@@ -141,7 +170,8 @@ static bool trusty_log_has_data(struct trusty_log_state *s,
 }
 
 /**
- * trusty_log_start() - initialize the sink iteration
+ * trusty_log_start() - initialize the sink iteration either to kernel log
+ * or to secondary log_sfile
  * @s:         Current log state.
  * @sink:      trusty_log_sink_state holding the get index on a given sink
  * @index:     Unwrapped ring buffer index from where iteration shall start
@@ -202,17 +232,177 @@ static void trusty_log_show(struct trusty_log_state *s,
 	 * have been corrupted by the producer.
 	 */
 	if (u32_sub_overflow(alloc, get) > log->sz) {
-		dev_err(s->dev, "log overflow.\n");
+		/*
+		 * this condition is acceptable in the case of the sfile sink
+		 * when attempting to read the oldest entry (at alloc-log->sz)
+		 * which may be overrun by a new one when ring buffer write
+		 * index wraps around.
+		 * So the overrun is not reported in case the oldest line
+		 * was being read.
+		 */
+		if (sink->sfile) {
+			if (!sink->ignore_overflow)
+				seq_puts(sink->sfile, "log overflow.\n");
+			/* coalesce subsequent contiguous overflows. */
+			sink->ignore_overflow = true;
+		} else {
+			dev_err(s->dev, "log overflow.\n");
+		}
 		sink->get = u32_sub_overflow(alloc, log->sz);
 		return;
 	}
 	/* compute next line index */
 	sink->get = u32_add_overflow(get, read_chars);
-	if (sink->trusty_panicked || __ratelimit(&trusty_log_rate_limit)) {
-		dev_info(s->dev, "%s", s->line_buffer);
-		/* next line after last successful get */
+	/* once a line is valid, ignore_overflow must be disabled */
+	sink->ignore_overflow = false;
+	if (sink->sfile) {
+		seq_printf(sink->sfile, "%s", s->line_buffer);
 		sink->last_successful_next = sink->get;
+	} else {
+		if (sink->trusty_panicked ||
+		    __ratelimit(&trusty_log_rate_limit)) {
+			dev_info(s->dev, "%s", s->line_buffer);
+			/* next line after last successful get */
+			sink->last_successful_next = sink->get;
+		}
+	}
+}
+
+static void *trusty_log_seq_start(struct seq_file *sfile, loff_t *pos)
+{
+	struct trusty_log_sfile *lb;
+	struct trusty_log_state *s;
+	struct log_rb *log;
+	struct trusty_log_sink_state *log_sfile_sink;
+	u32 index;
+	int rc;
+
+	if (WARN_ON(!pos))
+		return ERR_PTR(-EINVAL);
+
+	lb = sfile->private;
+	if (WARN_ON(!lb))
+		return ERR_PTR(-EINVAL);
+
+	log_sfile_sink = kzalloc(sizeof(*log_sfile_sink), GFP_KERNEL);
+	if (!log_sfile_sink)
+		return ERR_PTR(-ENOMEM);
+
+	s = container_of(lb, struct trusty_log_state, log_sfile);
+	log_sfile_sink->sfile = sfile;
+	log = s->log;
+	if (*pos == 0) {
+		/* start at the oldest line */
+		index = 0;
+		if (log->alloc > log->sz)
+			index = u32_sub_overflow(log->alloc, log->sz);
+	} else {
+		/*
+		 * '*pos>0': pos hold the 32bits unwrapped index from where
+		 * to start iterating
+		 */
+		index = (u32)*pos;
+	}
+	pr_debug("%s start=%u\n", __func__, index);
+
+	log_sfile_sink->ignore_overflow = true;
+	rc = trusty_log_start(s, log_sfile_sink, index);
+	if (rc < 0)
+		goto free_sink;
+
+	if (!trusty_log_has_data(s, log_sfile_sink))
+		goto free_sink;
+
+	return log_sfile_sink;
+
+free_sink:
+	pr_debug("%s kfree\n", __func__);
+	kfree(log_sfile_sink);
+	return rc < 0 ? ERR_PTR(rc) : NULL;
+}
+
+static void *trusty_log_seq_next(struct seq_file *sfile, void *v, loff_t *pos)
+{
+	struct trusty_log_sfile *lb;
+	struct trusty_log_state *s;
+	struct trusty_log_sink_state *log_sfile_sink = v;
+	int rc = 0;
+
+	if (WARN_ON(!log_sfile_sink))
+		return ERR_PTR(-EINVAL);
+
+	lb = sfile->private;
+	if (WARN_ON(!lb)) {
+		rc = -EINVAL;
+		goto end_of_iter;
+	}
+	s = container_of(lb, struct trusty_log_state, log_sfile);
+
+	if (WARN_ON(!pos)) {
+		rc = -EINVAL;
+		goto end_of_iter;
 	}
+	/*
+	 * When starting a virtual file sink, the start function is invoked
+	 * with a pos argument which value is set to zero.
+	 * Subsequent starts are invoked with pos being set to
+	 * the unwrapped read index (get).
+	 * Upon u32 wraparound, the get index could be reset to zero.
+	 * Thus a msb is used to distinguish the `get` zero value
+	 * from the `start of file` zero value.
+	 */
+	*pos = (1UL << 32) + log_sfile_sink->get;
+	if (!trusty_log_has_data(s, log_sfile_sink))
+		goto end_of_iter;
+
+	return log_sfile_sink;
+
+end_of_iter:
+	pr_debug("%s kfree\n", __func__);
+	kfree(log_sfile_sink);
+	return rc < 0 ? ERR_PTR(rc) : NULL;
+}
+
+static void trusty_log_seq_stop(struct seq_file *sfile, void *v)
+{
+	/*
+	 * When iteration completes or on error, the next callback frees
+	 * the sink structure and returns NULL/error-code.
+	 * In that case stop (being invoked with void* v set to the last next
+	 * return value) would be invoked with v == NULL or error code.
+	 * When user space stops the iteration earlier than the end
+	 * (in case of user-space memory allocation limit for example)
+	 * then the stop function receives a non NULL get pointer
+	 * and is in charge or freeing the sink structure.
+	 */
+	struct trusty_log_sink_state *log_sfile_sink = v;
+
+	/* nothing to do - sink structure already freed */
+	if (IS_ERR_OR_NULL(log_sfile_sink))
+		return;
+
+	kfree(log_sfile_sink);
+
+	pr_debug("%s kfree\n", __func__);
+}
+
+static int trusty_log_seq_show(struct seq_file *sfile, void *v)
+{
+	struct trusty_log_sfile *lb;
+	struct trusty_log_state *s;
+	struct trusty_log_sink_state *log_sfile_sink = v;
+
+	if (WARN_ON(!log_sfile_sink))
+		return -EINVAL;
+
+	lb = sfile->private;
+	if (WARN_ON(!lb))
+		return -EINVAL;
+
+	s = container_of(lb, struct trusty_log_state, log_sfile);
+
+	trusty_log_show(s, log_sfile_sink);
+	return 0;
 }
 
 static void trusty_dump_logs(struct trusty_log_state *s)
@@ -268,6 +458,81 @@ static int trusty_log_panic_notify(struct notifier_block *nb,
 	return NOTIFY_OK;
 }
 
+const struct seq_operations trusty_log_seq_ops = {
+	.start = trusty_log_seq_start,
+	.stop = trusty_log_seq_stop,
+	.next = trusty_log_seq_next,
+	.show = trusty_log_seq_show,
+};
+
+static int trusty_log_sfile_dev_open(struct inode *inode, struct file *file)
+{
+	struct trusty_log_sfile *ls;
+	struct seq_file *sfile;
+	int rc;
+
+	if (WARN_ON(!file->private_data))
+		return -EINVAL;
+
+	ls = container_of(file->private_data, struct trusty_log_sfile, misc);
+
+	file->private_data = NULL;
+	rc = seq_open(file, &trusty_log_seq_ops);
+	if (rc < 0)
+		return rc;
+
+	sfile = file->private_data;
+	if (WARN_ON(!sfile))
+		return -EINVAL;
+
+	sfile->private = ls;
+	return 0;
+}
+
+static const struct file_operations log_sfile_dev_operations = {
+	.owner = THIS_MODULE,
+	.open = trusty_log_sfile_dev_open,
+	.read = seq_read,
+	.release = seq_release,
+};
+
+static int trusty_log_sfile_register(struct trusty_log_state *s)
+{
+	int ret;
+	struct trusty_log_sfile *ls = &s->log_sfile;
+
+	if (WARN_ON(!ls))
+		return -EINVAL;
+
+	snprintf(ls->device_name, sizeof(ls->device_name),
+		 "trusty-log%d", s->dev->id);
+	ls->misc.minor = MISC_DYNAMIC_MINOR;
+	ls->misc.name = ls->device_name;
+	ls->misc.fops = &log_sfile_dev_operations;
+
+	ret = misc_register(&ls->misc);
+	if (ret) {
+		dev_err(s->dev,
+			"log_sfile error while doing misc_register ret=%d\n",
+			ret);
+		return ret;
+	}
+	dev_info(s->dev, "/dev/%s registered\n",
+		 ls->device_name);
+	return 0;
+}
+
+static void trusty_log_sfile_unregister(struct trusty_log_state *s)
+{
+	struct trusty_log_sfile *ls = &s->log_sfile;
+
+	misc_deregister(&ls->misc);
+	if (s->dev) {
+		dev_info(s->dev, "/dev/%s unregistered\n",
+			 ls->misc.name);
+	}
+}
+
 static bool trusty_supports_logging(struct device *device)
 {
 	int result;
@@ -355,10 +620,20 @@ static int trusty_log_probe(struct platform_device *pdev)
 			"failed to register panic notifier\n");
 		goto error_panic_notifier;
 	}
+
+	result = trusty_log_sfile_register(s);
+	if (result < 0) {
+		dev_err(&pdev->dev, "failed to register log_sfile\n");
+		goto error_log_sfile;
+	}
+
 	platform_set_drvdata(pdev, s);
 
 	return 0;
 
+error_log_sfile:
+	atomic_notifier_chain_unregister(&panic_notifier_list,
+					 &s->panic_notifier);
 error_panic_notifier:
 	trusty_call_notifier_unregister(s->trusty_dev, &s->call_notifier);
 error_call_notifier:
@@ -388,6 +663,7 @@ static int trusty_log_remove(struct platform_device *pdev)
 	struct trusty_log_state *s = platform_get_drvdata(pdev);
 	trusty_shared_mem_id_t mem_id = s->log_pages_shared_mem_id;
 
+	trusty_log_sfile_unregister(s);
 	atomic_notifier_chain_unregister(&panic_notifier_list,
 					 &s->panic_notifier);
 	trusty_call_notifier_unregister(s->trusty_dev, &s->call_notifier);