vmd(8): disambiguate log messages per vm and device.

The logging output from vmd(8) often specifies the function performing
the logging, but leaves which vm or vm device to guesswork and
reading tea leaves.

Change the logging formatting to prefix with information about the
specific vm and potentially the device subprocess. Most of this
logging is behind the "verbose" mode, but for warnings this will
clarify which vm or device logged the warning.

The format of vm/<name>/<device><index> is chosen to be concise and
less ugly than other approaches. This adjusts the process naming
for devices to match, dropping the use of brackets.

In the process of this change, updating log settings dynamically
via vmctl(8) is fixed by properly broadcasting that information to
the device subprocesses. The "vmm" process also now updates its own
state properly, so settings survive vm reboots.

ok mlarkin@

diff --git a/usr.sbin/vmd/log.c b/usr.sbin/vmd/log.c
index a6b0db9..c6fb9ad 100644 (file)
--- a/usr.sbin/vmd/log.c
+++ b/usr.sbin/vmd/log.c
@@ -1,4 +1,4 @@
-/*     $OpenBSD: log.c,v 1.8 2017/03/21 12:06:56 bluhm Exp $   */
+/*     $OpenBSD: log.c,v 1.9 2023/09/26 01:53:54 dv Exp $      */
 
 /*
  * Copyright (c) 2003, 2004 Henning Brauer <henning@openbsd.org>
@@ -24,30 +24,11 @@
 #include <errno.h>
 #include <time.h>
 
+#include "proc.h"
+
 static int      debug;
 static int      verbose;
-const char     *log_procname;
-
-void   log_init(int, int);
-void   log_procinit(const char *);
-void   log_setverbose(int);
-int    log_getverbose(void);
-void   log_warn(const char *, ...)
-           __attribute__((__format__ (printf, 1, 2)));
-void   log_warnx(const char *, ...)
-           __attribute__((__format__ (printf, 1, 2)));
-void   log_info(const char *, ...)
-           __attribute__((__format__ (printf, 1, 2)));
-void   log_debug(const char *, ...)
-           __attribute__((__format__ (printf, 1, 2)));
-void   logit(int, const char *, ...)
-           __attribute__((__format__ (printf, 2, 3)));
-void   vlog(int, const char *, va_list)
-           __attribute__((__format__ (printf, 2, 0)));
-__dead void fatal(const char *, ...)
-           __attribute__((__format__ (printf, 1, 2)));
-__dead void fatalx(const char *, ...)
-           __attribute__((__format__ (printf, 1, 2)));
+static char     log_procname[2048];
 
 void
 log_init(int n_debug, int facility)
@@ -56,7 +37,7 @@ log_init(int n_debug, int facility)
 
        debug = n_debug;
        verbose = n_debug;
-       log_procinit(__progname);
+       log_procinit("%s", __progname);
 
        if (!debug)
                openlog(__progname, LOG_PID | LOG_NDELAY, facility);
@@ -65,10 +46,12 @@ log_init(int n_debug, int facility)
 }
 
 void
-log_procinit(const char *procname)
+log_procinit(const char *fmt, ...)
 {
-       if (procname != NULL)
-               log_procname = procname;
+       va_list ap;
+       va_start(ap, fmt);
+       vsnprintf(log_procname, sizeof(log_procname), fmt, ap);
+       va_end(ap);
 }
 
 void
@@ -101,7 +84,7 @@ vlog(int pri, const char *fmt, va_list ap)
 
        if (debug) {
                /* best effort in out of mem situations */
-               if (asprintf(&nfmt, "%s\n", fmt) == -1) {
+               if (asprintf(&nfmt, "%s: %s\n", log_procname, fmt) == -1) {
                        vfprintf(stderr, fmt, ap);
                        fprintf(stderr, "\n");
                } else {

diff --git a/usr.sbin/vmd/proc.c b/usr.sbin/vmd/proc.c
index c9efad1..115a5dd 100644 (file)
--- a/usr.sbin/vmd/proc.c
+++ b/usr.sbin/vmd/proc.c
@@ -1,4 +1,4 @@
-/*     $OpenBSD: proc.c,v 1.20 2023/02/15 20:44:01 tobhe Exp $ */
+/*     $OpenBSD: proc.c,v 1.21 2023/09/26 01:53:54 dv Exp $    */
 
 /*
  * Copyright (c) 2010 - 2016 Reyk Floeter <reyk@openbsd.org>
@@ -287,7 +287,7 @@ proc_setup(struct privsep *ps, struct privsep_proc *procs, unsigned int nproc)
        struct privsep_pipes    *pp;
 
        /* Initialize parent title, ps_instances and procs. */
-       ps->ps_title[PROC_PARENT] = "parent";
+       ps->ps_title[PROC_PARENT] = "vmd";
 
        for (src = 0; src < PROC_MAX; src++)
                /* Default to 1 process instance */
@@ -514,7 +514,7 @@ proc_run(struct privsep *ps, struct privsep_proc *p,
        const char              *root;
        struct control_sock     *rcs;
 
-       log_procinit(p->p_title);
+       log_procinit("%s", p->p_title);
 
        /* Set the process group of the current process */
        setpgid(0, 0);

diff --git a/usr.sbin/vmd/proc.h b/usr.sbin/vmd/proc.h
index 1702bd9..5e000af 100644 (file)
--- a/usr.sbin/vmd/proc.h
+++ b/usr.sbin/vmd/proc.h
@@ -1,4 +1,4 @@
-/*     $OpenBSD: proc.h,v 1.22 2022/10/31 14:02:11 dv Exp $    */
+/*     $OpenBSD: proc.h,v 1.23 2023/09/26 01:53:54 dv Exp $    */
 
 /*
  * Copyright (c) 2010-2015 Reyk Floeter <reyk@openbsd.org>
@@ -190,7 +190,7 @@ int  control_listen(struct control_sock *);
 
 /* log.c */
 void   log_init(int, int);
-void   log_procinit(const char *);
+void   log_procinit(const char *, ...);
 void   log_setverbose(int);
 int    log_getverbose(void);
 void   log_warn(const char *, ...)

diff --git a/usr.sbin/vmd/vioblk.c b/usr.sbin/vmd/vioblk.c
index a743484..4dbd7f1 100644 (file)
--- a/usr.sbin/vmd/vioblk.c
+++ b/usr.sbin/vmd/vioblk.c
@@ -1,4 +1,4 @@
-/*     $OpenBSD: vioblk.c,v 1.8 2023/09/14 15:25:43 dv Exp $   */
+/*     $OpenBSD: vioblk.c,v 1.9 2023/09/26 01:53:54 dv Exp $   */
 
 /*
  * Copyright (c) 2023 Dave Voutila <dv@openbsd.org>
@@ -75,8 +75,6 @@ vioblk_main(int fd, int fd_vmm)
        off_t                    szp = 0;
        int                      i, ret, type;
 
-       log_procinit("vioblk");
-
        /*
         * stdio - needed for read/write to disk fds and channels to the vm.
         * vmm + proc - needed to create shared vm mappings.
@@ -118,7 +116,9 @@ vioblk_main(int fd, int fd_vmm)
        }
        vcp = &vm.vm_params.vmc_params;
        current_vm = &vm;
-       setproctitle("%s/vioblk[%d]", vcp->vcp_name, vioblk->idx);
+
+       setproctitle("%s/vioblk%d", vcp->vcp_name, vioblk->idx);
+       log_procinit("vm/%s/vioblk%d", vcp->vcp_name, vioblk->idx);
 
        /* Now that we have our vm information, we can remap memory. */
        ret = remap_guest_mem(&vm, fd_vmm);
@@ -154,7 +154,7 @@ vioblk_main(int fd, int fd_vmm)
                goto fail;
        }
        vioblk->capacity = szp / 512;
-       log_debug("%s: initialized vioblk[%d] with %s image (capacity=%lld)",
+       log_debug("%s: initialized vioblk%d with %s image (capacity=%lld)",
            __func__, vioblk->idx, disk_type(type), vioblk->capacity);
 
        /* If we're restoring hardware, reinitialize the virtqueue hva. */
@@ -434,6 +434,7 @@ dev_dispatch_vm(int fd, short event, void *arg)
        struct imsgbuf          *ibuf = &iev->ibuf;
        struct imsg              imsg;
        ssize_t                  n = 0;
+       int                      verbose;
 
        if (event & EV_READ) {
                if ((n = imsg_read(ibuf)) == -1 && errno != EAGAIN)
@@ -472,6 +473,11 @@ dev_dispatch_vm(int fd, short event, void *arg)
                case IMSG_VMDOP_UNPAUSE_VM:
                        log_debug("%s: unpausing", __func__);
                        break;
+               case IMSG_CTL_VERBOSE:
+                       IMSG_SIZE_CHECK(&imsg, &verbose);
+                       memcpy(&verbose, imsg.data, sizeof(verbose));
+                       log_setverbose(verbose);
+                       break;
                default:
                        log_warnx("%s: unhandled imsg type %d", __func__,
                            imsg.hdr.type);

diff --git a/usr.sbin/vmd/vionet.c b/usr.sbin/vmd/vionet.c
index c0fb24c..740296a 100644 (file)
--- a/usr.sbin/vmd/vionet.c
+++ b/usr.sbin/vmd/vionet.c
@@ -1,4 +1,4 @@
-/*     $OpenBSD: vionet.c,v 1.5 2023/09/23 12:31:41 dv Exp $   */
+/*     $OpenBSD: vionet.c,v 1.6 2023/09/26 01:53:54 dv Exp $   */
 
 /*
  * Copyright (c) 2023 Dave Voutila <dv@openbsd.org>
@@ -72,8 +72,6 @@ vionet_main(int fd, int fd_vmm)
        ssize_t                  sz;
        int                      ret;
 
-       log_procinit("vionet");
-
        /*
         * stdio - needed for read/write to disk fds and channels to the vm.
         * vmm + proc - needed to create shared vm mappings.
@@ -110,7 +108,8 @@ vionet_main(int fd, int fd_vmm)
        }
        vcp = &vm.vm_params.vmc_params;
        current_vm = &vm;
-       setproctitle("%s/vionet[%d]", vcp->vcp_name, vionet->idx);
+       setproctitle("%s/vionet%d", vcp->vcp_name, vionet->idx);
+       log_procinit("vm/%s/vionet%d", vcp->vcp_name, vionet->idx);
 
        /* Now that we have our vm information, we can remap memory. */
        ret = remap_guest_mem(&vm, fd_vmm);
@@ -688,6 +687,7 @@ dev_dispatch_vm(int fd, short event, void *arg)
        struct imsgbuf          *ibuf = &iev->ibuf;
        struct imsg              imsg;
        ssize_t                  n = 0;
+       int                      verbose;
 
        if (dev == NULL)
                fatalx("%s: missing vionet pointer", __func__);
@@ -739,6 +739,11 @@ dev_dispatch_vm(int fd, short event, void *arg)
                            & VIRTIO_CONFIG_DEVICE_STATUS_DRIVER_OK)
                                event_add(&ev_tap, NULL);
                        break;
+               case IMSG_CTL_VERBOSE:
+                       IMSG_SIZE_CHECK(&imsg, &verbose);
+                       memcpy(&verbose, imsg.data, sizeof(verbose));
+                       log_setverbose(verbose);
+                       break;
                }
                imsg_free(&imsg);
        }

diff --git a/usr.sbin/vmd/virtio.c b/usr.sbin/vmd/virtio.c
index 42710c5..e4795cf 100644 (file)
--- a/usr.sbin/vmd/virtio.c
+++ b/usr.sbin/vmd/virtio.c
@@ -1,4 +1,4 @@
-/*     $OpenBSD: virtio.c,v 1.108 2023/09/23 12:31:41 dv Exp $ */
+/*     $OpenBSD: virtio.c,v 1.109 2023/09/26 01:53:54 dv Exp $ */
 
 /*
  * Copyright (c) 2015 Mike Larkin <mlarkin@openbsd.org>
@@ -1144,6 +1144,7 @@ vionet_dump(int fd)
                        return (-1);
                }
 
+               /* Clear volatile state. Will reinitialize on restore. */
                temp.vionet.vq[RXQ].q_hva = NULL;
                temp.vionet.vq[TXQ].q_hva = NULL;
                temp.async_fd = -1;
@@ -1202,6 +1203,7 @@ vioblk_dump(int fd)
                        return (-1);
                }
 
+               /* Clear volatile state. Will reinitialize on restore. */
                temp.vioblk.vq[0].q_hva = NULL;
                temp.async_fd = -1;
                temp.sync_fd = -1;
@@ -1261,36 +1263,33 @@ virtio_dump(int fd)
        return (0);
 }
 
-void
-virtio_stop(struct vmd_vm *vm)
+void virtio_broadcast_imsg(struct vmd_vm *vm, uint16_t type, void *data,
+    uint16_t datalen)
 {
        struct virtio_dev *dev;
        int ret;
 
        SLIST_FOREACH(dev, &virtio_devs, dev_next) {
-               ret = imsg_compose_event(&dev->async_iev, IMSG_VMDOP_PAUSE_VM,
-                   0, 0, -1, NULL, 0);
+               ret = imsg_compose_event(&dev->async_iev, type, 0, 0, -1, data,
+                   datalen);
                if (ret == -1) {
-                       log_warnx("%s: failed to compose pause msg to device",
-                               __func__);
+                       log_warnx("%s: failed to broadcast imsg type %u",
+                           __func__, type);
                }
        }
+
 }
 
 void
-virtio_start(struct vmd_vm *vm)
+virtio_stop(struct vmd_vm *vm)
 {
-       struct virtio_dev *dev;
-       int ret;
+       return virtio_broadcast_imsg(vm, IMSG_VMDOP_PAUSE_VM, NULL, 0);
+}
 
-       SLIST_FOREACH(dev, &virtio_devs, dev_next) {
-               ret = imsg_compose_event(&dev->async_iev, IMSG_VMDOP_UNPAUSE_VM,
-                   0, 0, -1, NULL, 0);
-               if (ret == -1) {
-                       log_warnx("%s: failed to compose start msg to device",
-                           __func__);
-               }
-       }
+void
+virtio_start(struct vmd_vm *vm)
+{
+       return virtio_broadcast_imsg(vm, IMSG_VMDOP_UNPAUSE_VM, NULL, 0);
 }
 
 /*
@@ -1299,7 +1298,7 @@ virtio_start(struct vmd_vm *vm)
 static int
 virtio_dev_launch(struct vmd_vm *vm, struct virtio_dev *dev)
 {
-       char *nargv[10], num[32], vmm_fd[32], t[2];
+       char *nargv[12], num[32], vmm_fd[32], vm_name[VM_NAME_MAX], t[2];
        pid_t dev_pid;
        int data_fds[VM_MAX_BASE_PER_DISK], sync_fds[2], async_fds[2], ret = 0;
        size_t i, data_fds_sz, sz = 0;
@@ -1311,13 +1310,13 @@ virtio_dev_launch(struct vmd_vm *vm, struct virtio_dev *dev)
        case VMD_DEVTYPE_NET:
                data_fds[0] = dev->vionet.data_fd;
                data_fds_sz = 1;
-               log_debug("%s: launching vionet[%d]",
+               log_debug("%s: launching vionet%d",
                    vm->vm_params.vmc_params.vcp_name, dev->vionet.idx);
                break;
        case VMD_DEVTYPE_DISK:
                memcpy(&data_fds, dev->vioblk.disk_fd, sizeof(data_fds));
                data_fds_sz = dev->vioblk.ndisk_fd;
-               log_debug("%s: launching vioblk[%d]",
+               log_debug("%s: launching vioblk%d",
                    vm->vm_params.vmc_params.vcp_name, dev->vioblk.idx);
                break;
                /* NOTREACHED */
@@ -1463,6 +1462,9 @@ virtio_dev_launch(struct vmd_vm *vm, struct virtio_dev *dev)
                snprintf(num, sizeof(num), "%d", sync_fds[1]);
                memset(vmm_fd, 0, sizeof(vmm_fd));
                snprintf(vmm_fd, sizeof(vmm_fd), "%d", env->vmd_fd);
+               memset(vm_name, 0, sizeof(vm_name));
+               snprintf(vm_name, sizeof(vm_name), "%s",
+                   vm->vm_params.vmc_params.vcp_name);
 
                t[0] = dev->dev_type;
                t[1] = '\0';
@@ -1474,15 +1476,17 @@ virtio_dev_launch(struct vmd_vm *vm, struct virtio_dev *dev)
                nargv[4] = t;
                nargv[5] = "-i";
                nargv[6] = vmm_fd;
-               nargv[7] = "-n";
-               nargv[8] = NULL;
+               nargv[7] = "-p";
+               nargv[8] = vm_name;
+               nargv[9] = "-n";
+               nargv[10] = NULL;
 
                if (env->vmd_verbose == 1) {
-                       nargv[8] = VMD_VERBOSE_1;
-                       nargv[9] = NULL;
+                       nargv[10] = VMD_VERBOSE_1;
+                       nargv[11] = NULL;
                } else if (env->vmd_verbose > 1) {
-                       nargv[8] = VMD_VERBOSE_2;
-                       nargv[9] = NULL;
+                       nargv[10] = VMD_VERBOSE_2;
+                       nargv[11] = NULL;
                }
 
                /* Control resumes in vmd.c:main(). */

diff --git a/usr.sbin/vmd/virtio.h b/usr.sbin/vmd/virtio.h
index 8c1488e..2360863 100644 (file)
--- a/usr.sbin/vmd/virtio.h
+++ b/usr.sbin/vmd/virtio.h
@@ -1,4 +1,4 @@
-/*     $OpenBSD: virtio.h,v 1.48 2023/09/14 15:25:43 dv Exp $  */
+/*     $OpenBSD: virtio.h,v 1.49 2023/09/26 01:53:54 dv Exp $  */
 
 /*
  * Copyright (c) 2015 Mike Larkin <mlarkin@openbsd.org>
@@ -334,6 +334,7 @@ struct ioinfo {
 
 /* virtio.c */
 void virtio_init(struct vmd_vm *, int, int[][VM_MAX_BASE_PER_DISK], int *);
+void virtio_broadcast_imsg(struct vmd_vm *, uint16_t, void *, uint16_t);
 void virtio_stop(struct vmd_vm *);
 void virtio_start(struct vmd_vm *);
 void virtio_shutdown(struct vmd_vm *);

diff --git a/usr.sbin/vmd/vm.c b/usr.sbin/vmd/vm.c
index 115a60c..ee31c42 100644 (file)
--- a/usr.sbin/vmd/vm.c
+++ b/usr.sbin/vmd/vm.c
@@ -1,4 +1,4 @@
-/*     $OpenBSD: vm.c,v 1.93 2023/09/26 01:23:02 dv Exp $      */
+/*     $OpenBSD: vm.c,v 1.94 2023/09/26 01:53:54 dv Exp $      */
 
 /*
  * Copyright (c) 2015 Mike Larkin <mlarkin@openbsd.org>
@@ -257,7 +257,7 @@ vm_main(int fd, int vmm_fd)
        /* Update process with the vm name. */
        vcp = &vm.vm_params.vmc_params;
        setproctitle("%s", vcp->vcp_name);
-       log_procinit(vcp->vcp_name);
+       log_procinit("vm/%s", vcp->vcp_name);
 
        /* Receive the local prefix settings. */
        sz = atomicio(read, fd, &env->vmd_cfg.cfg_localprefix,
@@ -565,6 +565,8 @@ vm_dispatch_vmm(int fd, short event, void *arg)
                        IMSG_SIZE_CHECK(&imsg, &verbose);
                        memcpy(&verbose, imsg.data, sizeof(verbose));
                        log_setverbose(verbose);
+                       virtio_broadcast_imsg(vm, IMSG_CTL_VERBOSE, &verbose,
+                           sizeof(verbose));
                        break;
                case IMSG_VMDOP_VM_SHUTDOWN:
                        if (vmmci_ctl(VMMCI_SHUTDOWN) == -1)

diff --git a/usr.sbin/vmd/vmd.c b/usr.sbin/vmd/vmd.c
index 1b7cc32..a12b984 100644 (file)
--- a/usr.sbin/vmd/vmd.c
+++ b/usr.sbin/vmd/vmd.c
@@ -1,4 +1,4 @@
-/*     $OpenBSD: vmd.c,v 1.151 2023/07/03 08:32:20 jasper Exp $        */
+/*     $OpenBSD: vmd.c,v 1.152 2023/09/26 01:53:54 dv Exp $    */
 
 /*
  * Copyright (c) 2015 Reyk Floeter <reyk@openbsd.org>
@@ -439,7 +439,7 @@ vmd_dispatch_vmm(int fd, struct privsep_proc *p, struct imsg *imsg)
                        break;
                }
 
-               log_info("%s: started vm %d successfully, tty %s",
+               log_info("started %s (vm %d) successfully, tty %s",
                    vcp->vcp_name, vm->vm_vmid, vm->vm_ttyname);
                break;
        case IMSG_VMDOP_TERMINATE_VM_RESPONSE:
@@ -801,7 +801,7 @@ main(int argc, char **argv)
        if ((env = calloc(1, sizeof(*env))) == NULL)
                fatal("calloc: env");
 
-       while ((ch = getopt(argc, argv, "D:P:I:V:X:df:i:nt:v")) != -1) {
+       while ((ch = getopt(argc, argv, "D:P:I:V:X:df:i:nt:vp:")) != -1) {
                switch (ch) {
                case 'D':
                        if (cmdline_symset(optarg) < 0)
@@ -834,6 +834,9 @@ main(int argc, char **argv)
                                fatalx("invalid process instance");
                        break;
                /* child vm and device fork/exec */
+               case 'p':
+                       title = optarg;
+                       break;
                case 'V':
                        vm_launch = VMD_LAUNCH_VM;
                        vm_fd = strtonum(optarg, 0, 128, &errp);
@@ -908,9 +911,11 @@ main(int argc, char **argv)
                /* NOTREACHED */
        } else if (vm_launch == VMD_LAUNCH_DEV) {
                if (dev_type == VMD_DEVTYPE_NET) {
+                       log_procinit("vm/%s/vionet", title);
                        vionet_main(vm_fd, vmm_fd);
                        /* NOTREACHED */
                } else if (dev_type == VMD_DEVTYPE_DISK) {
+                       log_procinit("vm/%s/vioblk", title);
                        vioblk_main(vm_fd, vmm_fd);
                        /* NOTREACHED */
                }
@@ -941,7 +946,6 @@ main(int argc, char **argv)
        proc_init(ps, procs, nitems(procs), env->vmd_debug, argc0, argv,
            proc_id);
 
-       log_procinit("parent");
        if (!env->vmd_debug && daemon(0, 0) == -1)
                fatal("can't daemonize");
 
@@ -970,7 +974,7 @@ main(int argc, char **argv)
 
        event_dispatch();
 
-       log_debug("parent exiting");
+       log_debug("exiting");
 
        return (0);
 }
@@ -1164,7 +1168,7 @@ vmd_shutdown(void)
        proc_kill(&env->vmd_ps);
        free(env);
 
-       log_warnx("parent terminating");
+       log_warnx("terminating");
        exit(0);
 }
 

diff --git a/usr.sbin/vmd/vmm.c b/usr.sbin/vmd/vmm.c
index a48868c..b6b138a 100644 (file)
--- a/usr.sbin/vmd/vmm.c
+++ b/usr.sbin/vmd/vmm.c
@@ -1,4 +1,4 @@
-/*     $OpenBSD: vmm.c,v 1.114 2023/07/27 09:27:43 dv Exp $    */
+/*     $OpenBSD: vmm.c,v 1.115 2023/09/26 01:53:54 dv Exp $    */
 
 /*
  * Copyright (c) 2015 Mike Larkin <mlarkin@openbsd.org>
@@ -233,7 +233,7 @@ vmm_dispatch_parent(int fd, struct privsep_proc *p, struct imsg *imsg)
                IMSG_SIZE_CHECK(imsg, &verbose);
                memcpy(&verbose, imsg->data, sizeof(verbose));
                log_setverbose(verbose);
-
+               env->vmd_verbose = verbose;
                /* Forward message to each VM process */
                TAILQ_FOREACH(vm, env->vmd_vms, vm_entry) {
                        imsg_compose_event(&vm->vm_iev,