Xen devel - Sep 2013 - [PATCH v3] xen/console: buffer and show origin of guest PV writes

Guests other than domain 0 using the console output have previously been
controlled by the VERBOSE #define, but with no designation of which
guest''s output was on the console. This patch converts the HVM output
buffering to be used by all domains except the hardware domain (dom0):
stripping non-printable characters, line buffering the output, and
prefixing it with the domain ID. This is especially useful for debugging
stub domains during early boot.

Signed-off-by: Daniel De Graaf <dgdegra@tycho.nsa.gov>
Acked-by: Keir Fraser <keir@xen.org>
---
Changes since v2:
 - Clarified patch description

Changes since v1 (RFC):
 - Use prefix of (d%d) in place of (XEN) for both PV and HVM output
 - Guests other than dom0 have non-printable characters stripped
 - Use unsigned type for pbuf_idx
 - Formatting fixes

 xen/arch/x86/hvm/hvm.c           | 27 +++++-------
 xen/common/domain.c              |  8 ++++
 xen/drivers/char/console.c       | 94 ++++++++++++++++++++++++++++++++--------
 xen/include/asm-x86/hvm/domain.h |  6 ---
 xen/include/xen/lib.h            |  2 +
 xen/include/xen/sched.h          |  6 +++
 6 files changed, 103 insertions(+), 40 deletions(-)

diff --git a/xen/arch/x86/hvm/hvm.c b/xen/arch/x86/hvm/hvm.c
index ebf1838..8fd218e 100644
--- a/xen/arch/x86/hvm/hvm.c
+++ b/xen/arch/x86/hvm/hvm.c
@@ -485,8 +485,7 @@ static int hvm_set_ioreq_page(
 static int hvm_print_line(
     int dir, uint32_t port, uint32_t bytes, uint32_t *val)
 {
-    struct vcpu *curr = current;
-    struct hvm_domain *hd = &curr->domain->arch.hvm_domain;
+    struct domain *cd = current->domain;
     char c = *val;
 
     BUG_ON(bytes != 1);
@@ -495,17 +494,16 @@ static int hvm_print_line(
     if ( !isprint(c) && (c != ''\n'') && (c !=
''\t'') )
         return X86EMUL_OKAY;
 
-    spin_lock(&hd->pbuf_lock);
-    hd->pbuf[hd->pbuf_idx++] = c;
-    if ( (hd->pbuf_idx == (HVM_PBUF_SIZE - 2)) || (c ==
''\n'') )
+    spin_lock(&cd->pbuf_lock);
+    if ( c != ''\n'' )
+        cd->pbuf[cd->pbuf_idx++] = c;
+    if ( (cd->pbuf_idx == (DOMAIN_PBUF_SIZE - 1)) || (c ==
''\n'') )
     {
-        if ( c != ''\n'' )
-            hd->pbuf[hd->pbuf_idx++] = ''\n'';
-        hd->pbuf[hd->pbuf_idx] = ''\0'';
-        printk(XENLOG_G_DEBUG "HVM%u: %s",
curr->domain->domain_id, hd->pbuf);
-        hd->pbuf_idx = 0;
+        cd->pbuf[cd->pbuf_idx] = ''\0'';
+        guest_printk(cd, XENLOG_G_DEBUG "%s\n", cd->pbuf);
+        cd->pbuf_idx = 0;
     }
-    spin_unlock(&hd->pbuf_lock);
+    spin_unlock(&cd->pbuf_lock);
 
     return X86EMUL_OKAY;
 }
@@ -521,19 +519,16 @@ int hvm_domain_initialise(struct domain *d)
         return -EINVAL;
     }
 
-    spin_lock_init(&d->arch.hvm_domain.pbuf_lock);
     spin_lock_init(&d->arch.hvm_domain.irq_lock);
     spin_lock_init(&d->arch.hvm_domain.uc_lock);
 
     INIT_LIST_HEAD(&d->arch.hvm_domain.msixtbl_list);
     spin_lock_init(&d->arch.hvm_domain.msixtbl_list_lock);
 
-    d->arch.hvm_domain.pbuf = xzalloc_array(char, HVM_PBUF_SIZE);
     d->arch.hvm_domain.params = xzalloc_array(uint64_t, HVM_NR_PARAMS);
     d->arch.hvm_domain.io_handler = xmalloc(struct hvm_io_handler);
     rc = -ENOMEM;
-    if ( !d->arch.hvm_domain.pbuf || !d->arch.hvm_domain.params ||
-         !d->arch.hvm_domain.io_handler )
+    if ( !d->arch.hvm_domain.params || !d->arch.hvm_domain.io_handler )
         goto fail0;
     d->arch.hvm_domain.io_handler->num_slot = 0;
 
@@ -578,7 +573,6 @@ int hvm_domain_initialise(struct domain *d)
  fail0:
     xfree(d->arch.hvm_domain.io_handler);
     xfree(d->arch.hvm_domain.params);
-    xfree(d->arch.hvm_domain.pbuf);
     return rc;
 }
 
@@ -603,7 +597,6 @@ void hvm_domain_relinquish_resources(struct domain *d)
 
     xfree(d->arch.hvm_domain.io_handler);
     xfree(d->arch.hvm_domain.params);
-    xfree(d->arch.hvm_domain.pbuf);
 }
 
 void hvm_domain_destroy(struct domain *d)
diff --git a/xen/common/domain.c b/xen/common/domain.c
index 9390a22..5999779 100644
--- a/xen/common/domain.c
+++ b/xen/common/domain.c
@@ -231,6 +231,8 @@ struct domain *domain_create(
     spin_lock_init(&d->shutdown_lock);
     d->shutdown_code = -1;
 
+    spin_lock_init(&d->pbuf_lock);
+
     err = -ENOMEM;
     if ( !zalloc_cpumask_var(&d->domain_dirty_cpumask) )
         goto fail;
@@ -286,6 +288,10 @@ struct domain *domain_create(
         d->mem_event = xzalloc(struct mem_event_per_domain);
         if ( !d->mem_event )
             goto fail;
+
+        d->pbuf = xzalloc_array(char, DOMAIN_PBUF_SIZE);
+        if ( !d->pbuf )
+            goto fail;
     }
 
     if ( (err = arch_domain_create(d, domcr_flags)) != 0 )
@@ -318,6 +324,7 @@ struct domain *domain_create(
     d->is_dying = DOMDYING_dead;
     atomic_set(&d->refcnt, DOMAIN_DESTROYED);
     xfree(d->mem_event);
+    xfree(d->pbuf);
     if ( init_status & INIT_arch )
         arch_domain_destroy(d);
     if ( init_status & INIT_gnttab )
@@ -730,6 +737,7 @@ static void complete_domain_destroy(struct rcu_head *head)
 #endif
 
     xfree(d->mem_event);
+    xfree(d->pbuf);
 
     for ( i = d->max_vcpus - 1; i >= 0; i-- )
         if ( (v = d->vcpu[i]) != NULL )
diff --git a/xen/drivers/char/console.c b/xen/drivers/char/console.c
index e47ddf2..d5c0a06 100644
--- a/xen/drivers/char/console.c
+++ b/xen/drivers/char/console.c
@@ -24,6 +24,7 @@
 #include <xen/shutdown.h>
 #include <xen/video.h>
 #include <xen/kexec.h>
+#include <xen/ctype.h>
 #include <asm/debugger.h>
 #include <asm/div64.h>
 #include <xen/hypercall.h> /* for do_console_io */
@@ -375,6 +376,7 @@ static long guest_console_write(XEN_GUEST_HANDLE_PARAM(char)
buffer, int count)
 {
     char kbuf[128];
     int kcount;
+    struct domain *cd = current->domain;
 
     while ( count > 0 )
     {
@@ -388,19 +390,60 @@ static long
guest_console_write(XEN_GUEST_HANDLE_PARAM(char) buffer, int count)
             return -EFAULT;
         kbuf[kcount] = ''\0'';
 
-        spin_lock_irq(&console_lock);
+        if ( is_hardware_domain(cd) )
+        {
+            /* Use direct console output as it could be interactive */
+            spin_lock_irq(&console_lock);
+
+            sercon_puts(kbuf);
+            video_puts(kbuf);
 
-        sercon_puts(kbuf);
-        video_puts(kbuf);
+            if ( opt_console_to_ring )
+            {
+                conring_puts(kbuf);
+                tasklet_schedule(&notify_dom0_con_ring_tasklet);
+            }
 
-        if ( opt_console_to_ring )
+            spin_unlock_irq(&console_lock);
+        }
+        else
         {
-            conring_puts(kbuf);
-            tasklet_schedule(&notify_dom0_con_ring_tasklet);
+            char *kin = kbuf;
+            char *kout = kbuf;
+            char c;
+            /* Strip non-printable characters */
+            for ( ; ; )
+            {
+                c = *kin++;
+                if ( c == ''\0'' || c == ''\n''
)
+                    break;
+                if ( isprint(c) || c == ''\t'' )
+                    *kout++ = c;
+            }
+            *kout = ''\0'';
+            spin_lock(&cd->pbuf_lock);
+            if ( c == ''\n'' )
+            {
+                kcount = kin - kbuf;
+                cd->pbuf[cd->pbuf_idx] = ''\0'';
+                guest_printk(cd, XENLOG_G_DEBUG "%s%s\n",
cd->pbuf, kbuf);
+                cd->pbuf_idx = 0;
+            }
+            else if ( cd->pbuf_idx + kcount < (DOMAIN_PBUF_SIZE - 1) )
+            {
+                /* buffer the output until a newline */
+                memcpy(cd->pbuf + cd->pbuf_idx, kbuf, kcount);
+                cd->pbuf_idx += kcount;
+            }
+            else
+            {
+                cd->pbuf[cd->pbuf_idx] = ''\0'';
+                guest_printk(cd, XENLOG_G_DEBUG "%s%s\n",
cd->pbuf, kbuf);
+                cd->pbuf_idx = 0;
+            }
+            spin_unlock(&cd->pbuf_lock);
         }
 
-        spin_unlock_irq(&console_lock);
-
         guest_handle_add_offset(buffer, kcount);
         count -= kcount;
     }
@@ -504,12 +547,12 @@ static int printk_prefix_check(char *p, char **pp)
             ((loglvl < upper_thresh) && printk_ratelimit()));
 } 
 
-static void printk_start_of_line(void)
+static void printk_start_of_line(const char *prefix)
 {
     struct tm tm;
     char tstr[32];
 
-    __putstr("(XEN) ");
+    __putstr(prefix);
 
     if ( !opt_console_timestamps )
         return;
@@ -524,12 +567,11 @@ static void printk_start_of_line(void)
     __putstr(tstr);
 }
 
-void printk(const char *fmt, ...)
+static void vprintk_common(const char *prefix, const char *fmt, va_list args)
 {
     static char   buf[1024];
     static int    start_of_line = 1, do_print;
 
-    va_list       args;
     char         *p, *q;
     unsigned long flags;
 
@@ -537,9 +579,7 @@ void printk(const char *fmt, ...)
     local_irq_save(flags);
     spin_lock_recursive(&console_lock);
 
-    va_start(args, fmt);
     (void)vsnprintf(buf, sizeof(buf), fmt, args);
-    va_end(args);        
 
     p = buf;
 
@@ -551,7 +591,7 @@ void printk(const char *fmt, ...)
         if ( do_print )
         {
             if ( start_of_line )
-                printk_start_of_line();
+                printk_start_of_line(prefix);
             __putstr(p);
             __putstr("\n");
         }
@@ -566,7 +606,7 @@ void printk(const char *fmt, ...)
         if ( do_print )
         {
             if ( start_of_line )
-                printk_start_of_line();
+                printk_start_of_line(prefix);
             __putstr(p);
         }
         start_of_line = 0;
@@ -576,6 +616,26 @@ void printk(const char *fmt, ...)
     local_irq_restore(flags);
 }
 
+void printk(const char *fmt, ...)
+{
+    va_list args;
+    va_start(args, fmt);
+    vprintk_common("(XEN) ", fmt, args);
+    va_end(args);
+}
+
+void guest_printk(struct domain *d, const char *fmt, ...)
+{
+    va_list args;
+    char prefix[16];
+
+    snprintf(prefix, sizeof(prefix), "(d%d) ", d->domain_id);
+
+    va_start(args, fmt);
+    vprintk_common(prefix, fmt, args);
+    va_end(args);
+}
+
 void __init console_init_preirq(void)
 {
     char *p;
@@ -792,7 +852,7 @@ int __printk_ratelimit(int ratelimit_ms, int
ratelimit_burst)
             snprintf(lost_str, sizeof(lost_str), "%d", lost);
             /* console_lock may already be acquired by printk(). */
             spin_lock_recursive(&console_lock);
-            printk_start_of_line();
+            printk_start_of_line("(XEN) ");
             __putstr("printk: ");
             __putstr(lost_str);
             __putstr(" messages suppressed.\n");
diff --git a/xen/include/asm-x86/hvm/domain.h b/xen/include/asm-x86/hvm/domain.h
index 27b3de5..b1e3187 100644
--- a/xen/include/asm-x86/hvm/domain.h
+++ b/xen/include/asm-x86/hvm/domain.h
@@ -62,12 +62,6 @@ struct hvm_domain {
     /* emulated irq to pirq */
     struct radix_tree_root emuirq_pirq;
 
-    /* hvm_print_line() logging. */
-#define HVM_PBUF_SIZE 80
-    char                  *pbuf;
-    int                    pbuf_idx;
-    spinlock_t             pbuf_lock;
-
     uint64_t              *params;
 
     /* Memory ranges with pinned cache attributes. */
diff --git a/xen/include/xen/lib.h b/xen/include/xen/lib.h
index 74b34eb..40afe12 100644
--- a/xen/include/xen/lib.h
+++ b/xen/include/xen/lib.h
@@ -83,6 +83,8 @@ extern void debugtrace_printk(const char *fmt, ...);
 #define _p(_x) ((void *)(unsigned long)(_x))
 extern void printk(const char *format, ...)
     __attribute__ ((format (printf, 1, 2)));
+extern void guest_printk(struct domain *d, const char *format, ...)
+    __attribute__ ((format (printf, 2, 3)));
 extern void panic(const char *format, ...)
     __attribute__ ((format (printf, 1, 2)));
 extern long vm_assist(struct domain *, unsigned int, unsigned int);
diff --git a/xen/include/xen/sched.h b/xen/include/xen/sched.h
index ae6a3b8..0013a8d 100644
--- a/xen/include/xen/sched.h
+++ b/xen/include/xen/sched.h
@@ -341,6 +341,12 @@ struct domain
     /* Control-plane tools handle for this domain. */
     xen_domain_handle_t handle;
 
+    /* hvm_print_line() and guest_console_write() logging. */
+#define DOMAIN_PBUF_SIZE 80
+    char       *pbuf;
+    unsigned    pbuf_idx;
+    spinlock_t  pbuf_lock;
+
     /* OProfile support. */
     struct xenoprof *xenoprof;
     int32_t time_offset_seconds;
-- 
1.8.1.4