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,
