From ddadf9931e331f276c59347c121083d650eb92ea Mon Sep 17 00:00:00 2001 From: reyk Date: Tue, 10 Jul 2018 16:15:51 +0000 Subject: [PATCH] Tweak debug log messages - Turn tracing messages into DPRINTF (only compiled with DEBUG). - Pass __func__ to vm_stop and vm_remove: this way we can track who called the function in the async context. It replaces the manual log_debug in front of each vm_stop/vm_remove. This debug logging trick can be removed in the future once we are more confident about it. OK ccardenas@ mlarkin@ --- usr.sbin/vmd/config.c | 33 ++++++++++++------------- usr.sbin/vmd/vmd.c | 57 +++++++++++++++++++++++-------------------- usr.sbin/vmd/vmd.h | 6 ++--- usr.sbin/vmd/vmm.c | 23 ++++++++--------- 4 files changed, 59 insertions(+), 60 deletions(-) diff --git a/usr.sbin/vmd/config.c b/usr.sbin/vmd/config.c index 68561027053..fab9af708d4 100644 --- a/usr.sbin/vmd/config.c +++ b/usr.sbin/vmd/config.c @@ -1,4 +1,4 @@ -/* $OpenBSD: config.c,v 1.44 2018/06/19 18:15:01 reyk Exp $ */ +/* $OpenBSD: config.c,v 1.45 2018/07/10 16:15:51 reyk Exp $ */ /* * Copyright (c) 2015 Reyk Floeter @@ -80,8 +80,9 @@ config_purge(struct vmd *env, unsigned int reset) struct vmd_switch *vsw; unsigned int what; - log_debug("%s: %s purging vms and switches", + DPRINTF("%s: %s purging vms and switches", __func__, ps->ps_title[privsep_process]); + /* Reset global configuration (prefix was verified before) */ (void)host(VMD_DHCP_PREFIX, &env->vmd_cfg.cfg_localprefix); @@ -89,8 +90,7 @@ config_purge(struct vmd *env, unsigned int reset) what = ps->ps_what[privsep_process] & reset; if (what & CONFIG_VMS && env->vmd_vms != NULL) { while ((vm = TAILQ_FIRST(env->vmd_vms)) != NULL) { - log_debug("%s: calling vm_remove", __func__); - vm_remove(vm); + vm_remove(vm, __func__); } env->vmd_nvm = 0; } @@ -107,7 +107,8 @@ config_setconfig(struct vmd *env) struct privsep *ps = &env->vmd_ps; unsigned int id; - log_debug("%s: setting config", __func__); + DPRINTF("%s: setting config", __func__); + for (id = 0; id < PROC_MAX; id++) { if (id == privsep_process) continue; @@ -138,7 +139,8 @@ config_setreset(struct vmd *env, unsigned int reset) struct privsep *ps = &env->vmd_ps; unsigned int id; - log_debug("%s: resetting state", __func__); + DPRINTF("%s: resetting state", __func__); + for (id = 0; id < PROC_MAX; id++) { if ((reset & ps->ps_what[id]) == 0 || id == privsep_process) @@ -152,14 +154,14 @@ config_setreset(struct vmd *env, unsigned int reset) int config_getreset(struct vmd *env, struct imsg *imsg) { - struct privsep *ps = &env->vmd_ps; unsigned int mode; IMSG_SIZE_CHECK(imsg, &mode); memcpy(&mode, imsg->data, sizeof(mode)); log_debug("%s: %s resetting state", - __func__, ps->ps_title[privsep_process]); + __func__, env->vmd_ps.ps_title[privsep_process]); + config_purge(env, mode); return (0); @@ -423,11 +425,9 @@ config_setvm(struct privsep *ps, struct vmd_vm *vm, uint32_t peerid, uid_t uid) } if (vm->vm_from_config) { - log_debug("%s: calling stop vm %d", __func__, vm->vm_vmid); - vm_stop(vm, 0); + vm_stop(vm, 0, __func__); } else { - log_debug("%s: calling remove vm %d", __func__, vm->vm_vmid); - vm_remove(vm); + vm_remove(vm, __func__); } errno = saved_errno; if (errno == 0) @@ -460,8 +460,7 @@ config_getvm(struct privsep *ps, struct imsg *imsg) imsg->fd = -1; } - log_debug("%s: calling vm_remove", __func__); - vm_remove(vm); + vm_remove(vm, __func__); if (errno == 0) errno = EINVAL; @@ -485,7 +484,7 @@ config_getdisk(struct privsep *ps, struct imsg *imsg) if (n >= vm->vm_params.vmc_params.vcp_ndisks || vm->vm_disks[n] != -1 || imsg->fd == -1) { - log_debug("invalid disk id"); + log_warnx("invalid disk id"); errno = EINVAL; return (-1); } @@ -510,7 +509,7 @@ config_getif(struct privsep *ps, struct imsg *imsg) memcpy(&n, imsg->data, sizeof(n)); if (n >= vm->vm_params.vmc_params.vcp_nnics || vm->vm_ifs[n].vif_fd != -1 || imsg->fd == -1) { - log_debug("invalid interface id"); + log_warnx("invalid interface id"); goto fail; } vm->vm_ifs[n].vif_fd = imsg->fd; @@ -534,7 +533,7 @@ config_getcdrom(struct privsep *ps, struct imsg *imsg) } if (imsg->fd == -1) { - log_debug("invalid cdrom id"); + log_warnx("invalid cdrom id"); goto fail; } diff --git a/usr.sbin/vmd/vmd.c b/usr.sbin/vmd/vmd.c index 9b1c66e2a52..5f81cab8986 100644 --- a/usr.sbin/vmd/vmd.c +++ b/usr.sbin/vmd/vmd.c @@ -1,4 +1,4 @@ -/* $OpenBSD: vmd.c,v 1.87 2018/06/26 10:00:08 reyk Exp $ */ +/* $OpenBSD: vmd.c,v 1.88 2018/07/10 16:15:51 reyk Exp $ */ /* * Copyright (c) 2015 Reyk Floeter @@ -366,7 +366,7 @@ vmd_dispatch_vmm(int fd, struct privsep_proc *p, struct imsg *imsg) errno = vmr.vmr_result; log_warn("%s: failed to foward vm result", vcp->vcp_name); - vm_remove(vm); + vm_remove(vm, __func__); return (-1); } } @@ -374,14 +374,14 @@ vmd_dispatch_vmm(int fd, struct privsep_proc *p, struct imsg *imsg) if (vmr.vmr_result) { errno = vmr.vmr_result; log_warn("%s: failed to start vm", vcp->vcp_name); - vm_remove(vm); + vm_remove(vm, __func__); break; } /* Now configure all the interfaces */ if (vm_priv_ifconfig(ps, vm) == -1) { log_warn("%s: failed to configure vm", vcp->vcp_name); - vm_remove(vm); + vm_remove(vm, __func__); break; } @@ -391,7 +391,7 @@ vmd_dispatch_vmm(int fd, struct privsep_proc *p, struct imsg *imsg) case IMSG_VMDOP_TERMINATE_VM_RESPONSE: IMSG_SIZE_CHECK(imsg, &vmr); memcpy(&vmr, imsg->data, sizeof(vmr)); - log_debug("%s: forwarding TERMINATE VM for vm id %d", + DPRINTF("%s: forwarding TERMINATE VM for vm id %d", __func__, vmr.vmr_id); proc_forward_imsg(ps, imsg, PROC_CONTROL, -1); if ((vm = vm_getbyvmid(vmr.vmr_id)) == NULL) @@ -413,7 +413,7 @@ vmd_dispatch_vmm(int fd, struct privsep_proc *p, struct imsg *imsg) case IMSG_VMDOP_TERMINATE_VM_EVENT: IMSG_SIZE_CHECK(imsg, &vmr); memcpy(&vmr, imsg->data, sizeof(vmr)); - log_debug("%s: handling TERMINATE_EVENT for vm id %d ret %d", + DPRINTF("%s: handling TERMINATE_EVENT for vm id %d ret %d", __func__, vmr.vmr_id, vmr.vmr_result); if ((vm = vm_getbyvmid(vmr.vmr_id)) == NULL) { log_debug("%s: vm %d is no longer available", @@ -422,19 +422,13 @@ vmd_dispatch_vmm(int fd, struct privsep_proc *p, struct imsg *imsg) } if (vmr.vmr_result != EAGAIN) { if (vm->vm_from_config) { - log_debug("%s: about to stop vm id %d", - __func__, vm->vm_vmid); - vm_stop(vm, 0); + vm_stop(vm, 0, __func__); } else { - log_debug("%s: about to remove vm %d", - __func__, vm->vm_vmid); - vm_remove(vm); + vm_remove(vm, __func__); } } else { /* Stop VM instance but keep the tty open */ - log_debug("%s: about to stop vm id %d with tty open", - __func__, vm->vm_vmid); - vm_stop(vm, 1); + vm_stop(vm, 1, __func__); config_setvm(ps, vm, (uint32_t)-1, vm->vm_uid); } break; @@ -460,7 +454,7 @@ vmd_dispatch_vmm(int fd, struct privsep_proc *p, struct imsg *imsg) imsg->hdr.peerid, -1, &vir, sizeof(vir)) == -1) { log_debug("%s: GET_INFO_VM failed for vm %d, removing", __func__, vm->vm_vmid); - vm_remove(vm); + vm_remove(vm, __func__); return (-1); } break; @@ -491,7 +485,7 @@ vmd_dispatch_vmm(int fd, struct privsep_proc *p, struct imsg *imsg) sizeof(vir)) == -1) { log_debug("%s: GET_INFO_VM_END failed", __func__); - vm_remove(vm); + vm_remove(vm, __func__); return (-1); } } @@ -905,9 +899,9 @@ vmd_reload(unsigned int reset, const char *filename) TAILQ_FOREACH_SAFE(vm, env->vmd_vms, vm_entry, next_vm) { if (vm->vm_running == 0) { - log_debug("%s: calling vm_remove", + DPRINTF("%s: calling vm_remove", __func__); - vm_remove(vm); + vm_remove(vm, __func__); } } } @@ -963,8 +957,9 @@ vmd_shutdown(void) struct vmd_vm *vm, *vm_next; log_debug("%s: performing shutdown", __func__); + TAILQ_FOREACH_SAFE(vm, env->vmd_vms, vm_entry, vm_next) { - vm_remove(vm); + vm_remove(vm, __func__); } proc_kill(&env->vmd_ps); @@ -1053,14 +1048,18 @@ vm_getbypid(pid_t pid) } void -vm_stop(struct vmd_vm *vm, int keeptty) +vm_stop(struct vmd_vm *vm, int keeptty, const char *caller) { + struct privsep *ps = &env->vmd_ps; unsigned int i; if (vm == NULL) return; - log_debug("%s: stopping vm %d", __func__, vm->vm_vmid); + log_debug("%s: %s %s stopping vm %d%s", + __func__, ps->ps_title[privsep_process], caller, + vm->vm_vmid, keeptty ? ", keeping tty open" : ""); + vm->vm_running = 0; vm->vm_shutdown = 0; @@ -1101,16 +1100,20 @@ vm_stop(struct vmd_vm *vm, int keeptty) } void -vm_remove(struct vmd_vm *vm) +vm_remove(struct vmd_vm *vm, const char *caller) { + struct privsep *ps = &env->vmd_ps; + if (vm == NULL) return; - log_debug("%s: removing vm id %d from running config", - __func__, vm->vm_vmid); + log_debug("%s: %s %s removing vm %d from running config", + __func__, ps->ps_title[privsep_process], caller, + vm->vm_vmid); + TAILQ_REMOVE(env->vmd_vms, vm, vm_entry); - log_debug("%s: calling vm_stop", __func__); - vm_stop(vm, 0); + + vm_stop(vm, 0, caller); free(vm); } diff --git a/usr.sbin/vmd/vmd.h b/usr.sbin/vmd/vmd.h index 4daf3def8c7..9e5edc2c790 100644 --- a/usr.sbin/vmd/vmd.h +++ b/usr.sbin/vmd/vmd.h @@ -1,4 +1,4 @@ -/* $OpenBSD: vmd.h,v 1.70 2018/07/09 08:43:09 mlarkin Exp $ */ +/* $OpenBSD: vmd.h,v 1.71 2018/07/10 16:15:51 reyk Exp $ */ /* * Copyright (c) 2015 Mike Larkin @@ -308,8 +308,8 @@ uint32_t vm_id2vmid(uint32_t, struct vmd_vm *); uint32_t vm_vmid2id(uint32_t, struct vmd_vm *); struct vmd_vm *vm_getbyname(const char *); struct vmd_vm *vm_getbypid(pid_t); -void vm_stop(struct vmd_vm *, int); -void vm_remove(struct vmd_vm *); +void vm_stop(struct vmd_vm *, int, const char *); +void vm_remove(struct vmd_vm *, const char *); int vm_register(struct privsep *, struct vmop_create_params *, struct vmd_vm **, uint32_t, uid_t); int vm_checkperm(struct vmd_vm *, uid_t); diff --git a/usr.sbin/vmd/vmm.c b/usr.sbin/vmd/vmm.c index 9ff3cb6d692..918a4c545ac 100644 --- a/usr.sbin/vmd/vmm.c +++ b/usr.sbin/vmd/vmm.c @@ -1,4 +1,4 @@ -/* $OpenBSD: vmm.c,v 1.81 2018/04/13 17:12:44 martijn Exp $ */ +/* $OpenBSD: vmm.c,v 1.82 2018/07/10 16:15:51 reyk Exp $ */ /* * Copyright (c) 2015 Mike Larkin @@ -152,14 +152,15 @@ vmm_dispatch_parent(int fd, struct privsep_proc *p, struct imsg *imsg) IMSG_SIZE_CHECK(imsg, &vtp); memcpy(&vtp, imsg->data, sizeof(vtp)); id = vtp.vtp_vm_id; - log_debug("%s: recv'ed TERMINATE_VM for %d", __func__, id); + + DPRINTF("%s: recv'ed TERMINATE_VM for %d", __func__, id); if (id == 0) { res = ENOENT; } else if ((vm = vm_getbyvmid(id)) != NULL) { if (vm->vm_shutdown == 0) { - log_debug("%s: sending shutdown req to vm %d", - __func__, id); + log_debug("%s: sending shutdown request" + " to vm %d", __func__, id); /* * Request reboot but mark the VM as shutting @@ -302,7 +303,7 @@ vmm_dispatch_parent(int fd, struct privsep_proc *p, struct imsg *imsg) if ((vm = vm_getbyvmid(imsg->hdr.peerid)) != NULL) { log_debug("%s: removing vm, START_VM_RESPONSE", __func__); - vm_remove(vm); + vm_remove(vm, __func__); } } if (id == 0) @@ -382,8 +383,7 @@ vmm_sighdlr(int sig, short event, void *arg) log_warnx("could not terminate VM %u", vm->vm_vmid); - log_debug("%s: calling vm_remove", __func__); - vm_remove(vm); + vm_remove(vm, __func__); } else fatalx("unexpected cause of SIGCHLD"); } while (pid > 0 || (pid == -1 && errno == EINTR)); @@ -409,8 +409,7 @@ vmm_shutdown(void) /* XXX suspend or request graceful shutdown */ (void)terminate_vm(&vtp); - log_debug("%s: calling vm_remove", __func__); - vm_remove(vm); + vm_remove(vm, __func__); } } @@ -495,8 +494,7 @@ vmm_dispatch_vm(int fd, short event, void *arg) IMSG_SIZE_CHECK(&imsg, &vmr); memcpy(&vmr, imsg.data, sizeof(vmr)); if (!vmr.vmr_result) { - log_debug("%s: calling vm_remove", __func__); - vm_remove(vm); + vm_remove(vm, __func__); } case IMSG_VMDOP_PAUSE_VM_RESPONSE: case IMSG_VMDOP_UNPAUSE_VM_RESPONSE: @@ -674,8 +672,7 @@ vmm_start_vm(struct imsg *imsg, uint32_t *id) return (0); err: - log_debug("%s: calling vm_remove", __func__); - vm_remove(vm); + vm_remove(vm, __func__); return (ret); } -- 2.20.1