From 08d0da61ad3ca376416319ae810abe5d5ad26604 Mon Sep 17 00:00:00 2001 From: dv Date: Tue, 26 Sep 2023 01:53:54 +0000 Subject: [PATCH] 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// 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@ --- usr.sbin/vmd/log.c | 39 ++++++++--------------------- usr.sbin/vmd/proc.c | 6 ++--- usr.sbin/vmd/proc.h | 4 +-- usr.sbin/vmd/vioblk.c | 16 ++++++++---- usr.sbin/vmd/vionet.c | 13 +++++++--- usr.sbin/vmd/virtio.c | 58 +++++++++++++++++++++++-------------------- usr.sbin/vmd/virtio.h | 3 ++- usr.sbin/vmd/vm.c | 6 +++-- usr.sbin/vmd/vmd.c | 16 +++++++----- usr.sbin/vmd/vmm.c | 4 +-- 10 files changed, 85 insertions(+), 80 deletions(-) diff --git a/usr.sbin/vmd/log.c b/usr.sbin/vmd/log.c index a6b0db9c264..c6fb9ad9364 100644 --- 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 @@ -24,30 +24,11 @@ #include #include +#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 c9efad13ef3..115a5dde0b3 100644 --- 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 @@ -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 1702bd9756d..5e000af95c6 100644 --- 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 @@ -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 a74348441fa..4dbd7f129ad 100644 --- 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 @@ -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 c0fb24c0c40..740296a125e 100644 --- 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 @@ -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 42710c52e01..e4795cfb7e7 100644 --- 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 @@ -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 8c1488e98d1..23608635c85 100644 --- 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 @@ -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 115a60c3683..ee31c42cfbb 100644 --- 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 @@ -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 1b7cc3270c5..a12b9840a7a 100644 --- 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 @@ -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 a48868c8dd0..b6b138a6e3f 100644 --- 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 @@ -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, -- 2.20.1