It annoys me how all the log messages from different vmd vm's blur together. Here is a diff that makes them distinguishable. It also fixes dynamic toggling of verbosity levels in virtio devices using `vmctl log`, and now preserves the verbosity across vm reboots.
I chose the pattern "vm/<vm name> and "vm/<vm name>/<device><index> to distinguish between vmd procs and the names of vm's since someone could name their vm "vmd" or "vmm" or "priv" etc. Additionally, I'm proposing to change the proc titles for devices to use "<vm name>/<device><index>" instead of "<vm name>/<device>[<index>]" to match the logging format. While here I changed the name "parent" to "vmd". Feedback? Ok? -dv Sample abbreviated output of `$(which vmd) -dvv` (aka `vmctl log verbose`) when launching a vm named "alpine": vmd: startup <snip> vmd: start_vm_batch: done starting vms priv: config_getconfig: priv retrieving config agentx: config_getconfig: agentx retrieving config vmm: config_getconfig: vmm retrieving config control: config_getconfig: control retrieving config <snip> vm/alpine: alpine: launching vioblk0 vm/alpine: virtio_dev_launch: sending 'd' type device struct vm/alpine: virtio_dev_launch: marking fd 7 !close-on-exec vm/alpine: virtio_dev_launch: sending vm message for 'alpine' vm/alpine/vioblk: vioblk_main: got viblk dev. num disk fds = 1, sync fd = 16, async fd = 18, capacity = 0 seg_max = 126, vmm fd = 5 vm/alpine/vioblk0: qc2_open: qcow2 disk version 3 size 42949672960 end 6042222592 snap 0 vm/alpine/vioblk0: vioblk_main: initialized vioblk0 with qcow2 image (capacity=83886080) vm/alpine/vioblk0: vioblk_main: wiring in async vm event handler (fd=18) vm/alpine/vioblk0: vm_device_pipe: initializing 'd' device pipe (fd=18) vm/alpine/vioblk0: vioblk_main: wiring in sync channel handler (fd=16) vm/alpine/vioblk0: vioblk_main: telling vm alpine device is ready vm/alpine/vioblk0: vioblk_main: sending heartbeat vm/alpine: virtio_dev_launch: receiving reply vm/alpine: virtio_dev_launch: device reports ready via sync channel diff refs/heads/master refs/heads/vmd-logging commit - 6332535f639065d7cf3e5fc071339d6e7a72e767 commit + 0154c36753c63e89d2f4005e4fdc6a3ff17d174f blob - a6b0db9c264a7ca77411c0bc68a958bc226b317a blob + 1dd2a384fa24410474fd50de0c594e6f1e2e2bfc --- usr.sbin/vmd/log.c +++ usr.sbin/vmd/log.c @@ -24,31 +24,12 @@ #include <errno.h> #include <time.h> +#include "proc.h" + static int debug; static int verbose; -const char *log_procname; +static char log_procname[2048]; -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))); - 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 { blob - c9efad13ef3a504bbd43e2b26336784baca33db9 blob + 0b71a9a33e4ded6dac468196ba448fb1623ee137 --- usr.sbin/vmd/proc.c +++ usr.sbin/vmd/proc.c @@ -287,7 +287,7 @@ proc_setup(struct privsep *ps, struct privsep_proc *pr 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); blob - 1702bd9756d2442abf54cefe8f11b374bd2b2158 blob + bdc2de0c7a89bf16f1c337e693a9dcfaacfb683c --- usr.sbin/vmd/proc.h +++ usr.sbin/vmd/proc.h @@ -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 *, ...) blob - a74348441faefc3ac43d6a9cf0495bd6fcaca224 blob + fcdfb3840df49c82d194e2b71c9d172d1eeb1127 --- usr.sbin/vmd/vioblk.c +++ usr.sbin/vmd/vioblk.c @@ -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,8 +116,10 @@ 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); if (ret) { @@ -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); blob - 5123ad4c1d6d0fb89b6f66e1177be431888ffa2d blob + 783b54c2a59ace519fced2a5207b546982cfe057 --- usr.sbin/vmd/vionet.c +++ usr.sbin/vmd/vionet.c @@ -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); } blob - 203594c56932049d5937abc31b89e136fca1577a blob + c320ff124dc0a1efc68d8e7e3e129bb0cb3091fa --- usr.sbin/vmd/virtio.c +++ usr.sbin/vmd/virtio.c @@ -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_broadcast(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, type, 0, 0, -1, data, + datalen); + if (ret == -1) { + log_warnx("%s: failed to broadcast imsg type %u", + __func__, type); + } + } + +} + void virtio_stop(struct vmd_vm *vm) { - 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); - if (ret == -1) { - log_warnx("%s: failed to compose pause msg to device", - __func__); - } - } + return virtio_broadcast(vm, IMSG_VMDOP_PAUSE_VM, NULL, 0); } void virtio_start(struct vmd_vm *vm) { - struct virtio_dev *dev; - int ret; - - 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__); - } - } + return virtio_broadcast(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 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 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 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(). */ blob - 8c1488e98d1e356a5917cbafed4b64d67983f925 blob + 81958765cfe4474b57ca95baea948e04e94123da --- usr.sbin/vmd/virtio.h +++ usr.sbin/vmd/virtio.h @@ -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(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 *); blob - 15c1dd992df8f5ebdffc1bfc94aa56f332dec7e7 blob + 5f2fd3d640e0e683fe404b38ac680a6c07340de3 --- usr.sbin/vmd/vm.c +++ usr.sbin/vmd/vm.c @@ -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(vm, IMSG_CTL_VERBOSE, &verbose, + sizeof(verbose)); break; case IMSG_VMDOP_VM_SHUTDOWN: if (vmmci_ctl(VMMCI_SHUTDOWN) == -1) blob - 1b7cc3270c56b08a1577224087e4863b07b2c847 blob + 1422137f6041db7f0bf300a68861a3b3701e359c --- usr.sbin/vmd/vmd.c +++ usr.sbin/vmd/vmd.c @@ -439,7 +439,7 @@ vmd_dispatch_vmm(int fd, struct privsep_proc *p, struc 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); } blob - a48868c8dd044ca4fd7292eebb42bfc181d1ccc3 blob + 08e4f875befd3f20fd783fd35e48d142e81e04a0 --- usr.sbin/vmd/vmm.c +++ usr.sbin/vmd/vmm.c @@ -233,7 +233,7 @@ vmm_dispatch_parent(int fd, struct privsep_proc *p, st 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,