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@

diff --git a/usr.sbin/vmd/config.c b/usr.sbin/vmd/config.c
index 6856102..fab9af7 100644 (file)
--- 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 <reyk@openbsd.org>
@@ -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 9b1c66e..5f81cab 100644 (file)
--- 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 <reyk@openbsd.org>
@@ -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 4daf3de..9e5edc2 100644 (file)
--- 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 <mlarkin@openbsd.org>
@@ -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 9ff3cb6..918a4c5 100644 (file)
--- 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 <mlarkin@openbsd.org>
@@ -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);
 }