[Devel] [PATCH hci-8.1 4/6] ve/printk: Fix time virtualization

[Vladimir Riabchun <vladimir.riabchun@virtuozzo.com>]

The usage of get_exec_env() in ve_timens_add_boottime_ns can lead
to time travels - a printk from IRQ might use container time for
printing to host dmesg and vice versa.

Fix this by adding timens_offsets info to printk_info entry. This way
correct time is provided by the original printer of message, rather than
printing job, that may be delayed and called from a different context.
It seems complicated to keep time namespace in log_state, because
VE creation and namespace creation happen at different times and it
seems that one VE can have different time namespaces if it was stopped
and then started again.
So instead of tracking time namespaces, let's put actual time offsets
into log state.

https://virtuozzo.atlassian.net/browse/VSTOR-146839

Feature: ve printk
Signed-off-by: Vladimir Riabchun <vladimir.riabchun@virtuozzo.com>
---
 kernel/printk/internal.h          |  6 +++++
 kernel/printk/printk.c            | 51 ++++++++++++++++++++++++---------------
 kernel/printk/printk_ringbuffer.h |  2 ++
 3 files changed, 39 insertions(+), 20 deletions(-)

diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index d00ac40d8401..d0096aba5af7 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -4,6 +4,7 @@
  */
 #include <linux/console.h>
 #include <linux/percpu.h>
+#include <linux/time_namespace.h>
 #include <linux/types.h>
 
 #if defined(CONFIG_PRINTK) && defined(CONFIG_SYSCTL)
@@ -354,11 +355,16 @@ struct log_state {
 	 */
 	struct latched_seq clear_seq;
 	struct printk_ringbuffer *prb;
+	/* Updated on every log_state request */
+	struct timens_offsets time_offset;
 };
 
+#define GET_VE_LOG(ve) ((struct log_state *) ve->log_state)
+
 extern struct log_state init_log_state;
 
 struct log_state *ve_log_state(void);
+struct log_state *__ve_log_state(struct ve_struct *ve);
 
 bool printk_get_next_message(struct log_state *log,
 			     struct printk_message *pmsg, u64 seq,
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index df7cf83fb4af..575bd3590198 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -556,13 +556,28 @@ DEFINE_STRUCT_MEMBER_ALIAS(clear_seq, init_log_state, clear_seq);
 DEFINE_STRUCT_MEMBER_ALIAS(prb, init_log_state, prb);
 #undef DEFINE_STRUCT_MEMBER_ALIAS
 
+static void update_log_time(struct ve_struct *ve)
+{
+	struct time_namespace *timens = ve_get_time_ns(ve);
+
+	if (timens)
+		GET_VE_LOG(ve)->time_offset = timens->offsets;
+	else
+		GET_VE_LOG(ve)->time_offset = init_time_ns.offsets;
+
+	if (timens)
+		put_time_ns(timens);
+}
+
 struct log_state *ve_log_state(void)
 {
 	struct log_state *log = &init_log_state;
 #ifdef CONFIG_VE
 	/* get_exec_env() is reliable only in task context */
-	if (!WARN_ON_ONCE(!in_task()) && get_exec_env()->log_state)
+	if (!WARN_ON_ONCE(!in_task()) && get_exec_env()->log_state) {
+		update_log_time(get_exec_env());
 		log = get_exec_env()->log_state;
+	}
 #endif
 	return log;
 }
@@ -571,8 +586,10 @@ struct log_state *__ve_log_state(struct ve_struct *ve)
 {
 	struct log_state *log = &init_log_state;
 #ifdef CONFIG_VE
-	if (ve->log_state)
+	if (ve->log_state) {
+		update_log_time(ve);
 		log = ve->log_state;
+	}
 #endif
 	return log;
 }
@@ -698,21 +715,10 @@ static void append_char(char **pp, char *e, char c)
 		*(*pp)++ = c;
 }
 
-static inline u64 ve_timens_add_boottime_ns(u64 nsec)
+static inline u64 ve_timens_add_boottime_ns(u64 nsec, const struct timens_offsets *off)
 {
-	struct time_namespace *ve_time_ns;
-	struct timens_offsets *ns_offsets;
-
-	ve_time_ns = ve_get_time_ns(get_exec_env());
-	if (unlikely(!ve_time_ns)) {
-		/* container not yet started */
-		return nsec;
-	}
-
-	ns_offsets = &ve_time_ns->offsets;
-	nsec += ns_offsets->boottime.tv_sec * NSEC_PER_SEC;
-	nsec += ns_offsets->boottime.tv_nsec;
-	put_time_ns(ve_time_ns);
+	nsec += off->boottime.tv_sec * NSEC_PER_SEC;
+	nsec += off->boottime.tv_nsec;
 
 	return nsec;
 }
@@ -732,7 +738,7 @@ static ssize_t info_print_ext_header(char *buf, size_t size,
 #endif
 
 	/* shift the timestamp on the Container uptime value */
-	ts_usec = ve_timens_add_boottime_ns(ts_usec);
+	ts_usec = ve_timens_add_boottime_ns(ts_usec, &info->time_offset);
 	do_div(ts_usec, 1000);
 
 	return scnprintf(buf, size, "%u,%llu,%llu,%c%s;",
@@ -1108,6 +1114,7 @@ void log_buf_vmcoreinfo_setup(void)
 	VMCOREINFO_OFFSET(printk_info, text_len);
 	VMCOREINFO_OFFSET(printk_info, caller_id);
 	VMCOREINFO_OFFSET(printk_info, dev_info);
+	VMCOREINFO_OFFSET(printk_info, time_offset);
 
 	VMCOREINFO_STRUCT_SIZE(dev_printk_info);
 	VMCOREINFO_OFFSET(dev_printk_info, subsystem);
@@ -1219,6 +1226,7 @@ static unsigned int __init add_to_rb(struct printk_ringbuffer *rb,
 	dest_r.info->ts_nsec = r->info->ts_nsec;
 	dest_r.info->caller_id = r->info->caller_id;
 	memcpy(&dest_r.info->dev_info, &r->info->dev_info, sizeof(dest_r.info->dev_info));
+	dest_r.info->time_offset = r->info->time_offset;
 
 	prb_final_commit(&e);
 
@@ -1427,12 +1435,13 @@ static size_t print_syslog(unsigned int level, char *buf)
 	return sprintf(buf, "<%u>", level);
 }
 
-static size_t print_time(u64 ts, char *buf)
+static size_t print_time(const struct printk_info *info, char *buf)
 {
 	unsigned long rem_nsec;
+	u64 ts;
 
 	/* shift the timestamp on the Container uptime value */
-	ts = ve_timens_add_boottime_ns(ts);
+	ts = ve_timens_add_boottime_ns(info->ts_nsec, &info->time_offset);
 
 	rem_nsec = do_div(ts, 1000000000);
 
@@ -1462,7 +1471,7 @@ static size_t info_print_prefix(const struct printk_info  *info, bool syslog,
 		len = print_syslog((info->facility << 3) | info->level, buf);
 
 	if (time)
-		len += print_time(info->ts_nsec, buf + len);
+		len += print_time(info, buf + len);
 
 	len += print_caller(info->caller_id, buf + len);
 
@@ -2402,6 +2411,8 @@ static int vprintk_store_log(struct log_state *log, int facility, int level,
 	if (dev_info)
 		memcpy(&r.info->dev_info, dev_info, sizeof(r.info->dev_info));
 
+	r.info->time_offset = log->time_offset;
+
 	/* A message without a trailing newline can be continued. */
 	if (!(flags & LOG_NEWLINE))
 		prb_commit(&e);
diff --git a/kernel/printk/printk_ringbuffer.h b/kernel/printk/printk_ringbuffer.h
index 4ef81349d9fb..19052ba005fc 100644
--- a/kernel/printk/printk_ringbuffer.h
+++ b/kernel/printk/printk_ringbuffer.h
@@ -7,6 +7,7 @@
 #include <linux/bits.h>
 #include <linux/dev_printk.h>
 #include <linux/stddef.h>
+#include <linux/time_namespace.h>
 #include <linux/types.h>
 
 /*
@@ -25,6 +26,7 @@ struct printk_info {
 	u32	caller_id;	/* thread id or processor id */
 
 	struct dev_printk_info	dev_info;
+	struct timens_offsets	time_offset;	/* Author timens offsets */
 };
 
 /*

-- 
2.52.0

_______________________________________________
Devel mailing list
Devel@openvz.org
https://lists.openvz.org/mailman/listinfo/devel