Add log_debug statements in key places to assist with
troubleshooting.
diff --git usr.sbin/vmd/config.c usr.sbin/vmd/config.c
index 9ea87eb86e8..623a9b9d4f3 100644
--- usr.sbin/vmd/config.c
+++ usr.sbin/vmd/config.c
@@ -81,14 +81,18 @@ config_purge(struct vmd *env, unsigned int reset)
struct vmd_switch *vsw;
unsigned int what;
+ log_debug("%s: purging vms and switches from running config",
+ __func__);
/* Reset global configuration (prefix was verified before) */
(void)host(VMD_DHCP_PREFIX, &env->vmd_cfg.cfg_localprefix);
/* Reset other configuration */
what = ps->ps_what[privsep_process] & reset;
if (what & CONFIG_VMS && env->vmd_vms != NULL) {
- while ((vm = TAILQ_FIRST(env->vmd_vms)) != NULL)
+ while ((vm = TAILQ_FIRST(env->vmd_vms)) != NULL) {
+ log_debug("%s: calling vm_remove", __func__);
vm_remove(vm);
+ }
env->vmd_nvm = 0;
}
if (what & CONFIG_SWITCHES && env->vmd_switches != NULL) {
@@ -104,6 +108,7 @@ config_setconfig(struct vmd *env)
struct privsep *ps = &env->vmd_ps;
unsigned int id;
+ log_debug("%s: setting config", __func__);
for (id = 0; id < PROC_MAX; id++) {
if (id == privsep_process)
continue;
@@ -117,6 +122,7 @@ config_setconfig(struct vmd *env)
int
config_getconfig(struct vmd *env, struct imsg *imsg)
{
+ log_debug("%s: retrieving config", __func__);
IMSG_SIZE_CHECK(imsg, &env->vmd_cfg);
memcpy(&env->vmd_cfg, imsg->data, sizeof(env->vmd_cfg));
@@ -129,6 +135,7 @@ config_setreset(struct vmd *env, unsigned int reset)
struct privsep *ps = &env->vmd_ps;
unsigned int id;
+ log_debug("%s: resetting state", __func__);
for (id = 0; id < PROC_MAX; id++) {
if ((reset & ps->ps_what[id]) == 0 ||
id == privsep_process)
@@ -147,6 +154,7 @@ config_getreset(struct vmd *env, struct imsg *imsg)
IMSG_SIZE_CHECK(imsg, &mode);
memcpy(&mode, imsg->data, sizeof(mode));
+ log_debug("%s: resetting state", __func__);
config_purge(env, mode);
return (0);
@@ -374,6 +382,7 @@ config_setvm(struct privsep *ps, struct vmd_vm *vm,
uint32_t peerid, uid_t uid)
free(tapfds);
}
+ log_debug("%s: calling vm_remove", __func__);
vm_remove(vm);
errno = saved_errno;
if (errno == 0)
@@ -406,6 +415,7 @@ config_getvm(struct privsep *ps, struct imsg *imsg)
imsg->fd = -1;
}
+ log_debug("%s: calling vm_remove", __func__);
vm_remove(vm);
if (errno == 0)
errno = EINVAL;
diff --git usr.sbin/vmd/control.c usr.sbin/vmd/control.c
index 1af8a0d5e14..9263d0a3ae1 100644
--- usr.sbin/vmd/control.c
+++ usr.sbin/vmd/control.c
@@ -276,6 +276,7 @@ control_close(int fd, struct control_sock *cs)
{
struct ctl_conn *c;
+ log_debug("%s", __func__);
if ((c = control_connbyfd(fd)) == NULL) {
log_warn("%s: fd %d: not found", __func__, fd);
return;
@@ -401,9 +402,14 @@ control_dispatch_imsg(int fd, short event, void *arg)
goto fail;
memcpy(&vid, imsg.data, sizeof(vid));
vid.vid_uid = c->peercred.uid;
+ log_debug("%s vid: %d, name: %s, uid: %d",
+ __func__, vid.vid_id, vid.vid_name,
+ vid.vid_uid);
if (proc_compose_imsg(ps, PROC_PARENT, -1,
imsg.hdr.type, fd, -1, &vid, sizeof(vid)) == -1) {
+ log_debug("%s: proc_compose_imsg failed...",
+ __func__);
control_close(fd, cs);
return;
}
diff --git usr.sbin/vmd/proc.c usr.sbin/vmd/proc.c
index 183db93a678..2bf0a98c8ee 100644
--- usr.sbin/vmd/proc.c
+++ usr.sbin/vmd/proc.c
@@ -756,6 +756,8 @@ proc_compose_imsg(struct privsep *ps, enum privsep_procid
id, int n,
proc_range(ps, id, &n, &m);
for (; n < m; n++) {
+ log_debug("%s: about to compose_event to PROC %d", __func__,
+ id);
if (imsg_compose_event(&ps->ps_ievs[id][n],
type, peerid, ps->ps_instance + 1, fd, data, datalen) == -1)
return (-1);
diff --git usr.sbin/vmd/vmd.c usr.sbin/vmd/vmd.c
index c7b9247d326..f34917e1a3b 100644
--- usr.sbin/vmd/vmd.c
+++ usr.sbin/vmd/vmd.c
@@ -372,6 +372,8 @@ 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 %d",
+ __func__, vmr.vmr_id);
proc_forward_imsg(ps, imsg, PROC_CONTROL, -1);
if ((vm = vm_getbyvmid(vmr.vmr_id)) == NULL)
break;
@@ -392,15 +394,24 @@ 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 %d",
+ __func__, vmr.vmr_id);
if ((vm = vm_getbyvmid(vmr.vmr_id)) == NULL)
break;
if (vmr.vmr_result == 0) {
- if (vm->vm_from_config)
+ if (vm->vm_from_config) {
+ log_debug("%s: about to stop vm %d",
+ __func__, vm->vm_vmid);
vm_stop(vm, 0);
- else
+ } else {
+ log_debug("%s: about to remove vm %d",
+ __func__, vm->vm_vmid);
vm_remove(vm);
+ }
} else if (vmr.vmr_result == EAGAIN) {
/* Stop VM instance but keep the tty open */
+ log_debug("%s: about to stop vm %d with tty open",
+ __func__, vm->vm_vmid);
vm_stop(vm, 1);
config_setvm(ps, vm, (uint32_t)-1, 0);
}
@@ -425,6 +436,8 @@ vmd_dispatch_vmm(int fd, struct privsep_proc *p, struct
imsg *imsg)
}
if (proc_compose_imsg(ps, PROC_CONTROL, -1, imsg->hdr.type,
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);
return (-1);
}
@@ -453,6 +466,8 @@ vmd_dispatch_vmm(int fd, struct privsep_proc *p, struct
imsg *imsg)
IMSG_VMDOP_GET_INFO_VM_DATA,
imsg->hdr.peerid, -1, &vir,
sizeof(vir)) == -1) {
+ log_debug("%s: GET_INFO_VM_END failed",
+ __func__);
vm_remove(vm);
return (-1);
}
@@ -592,6 +607,7 @@ vmd_sighdlr(int sig, short event, void *arg)
{
if (privsep_process != PROC_PARENT)
return;
+ log_debug("%s: handling signal", __func__);
switch (sig) {
case SIGHUP:
@@ -862,8 +878,11 @@ vmd_reload(unsigned int reset, const char *filename)
if (reload) {
TAILQ_FOREACH_SAFE(vm, env->vmd_vms, vm_entry, next_vm)
{
- if (vm->vm_running == 0)
+ if (vm->vm_running == 0) {
+ log_debug("%s: calling vm_remove",
+ __func__);
vm_remove(vm);
+ }
}
/* Update shared global configuration in all children */
@@ -914,6 +933,7 @@ 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);
}
@@ -1011,6 +1031,7 @@ vm_stop(struct vmd_vm *vm, int keeptty)
if (vm == NULL)
return;
+ log_debug("%s: stopping vm %d", __func__, vm->vm_vmid);
vm->vm_running = 0;
vm->vm_shutdown = 0;
@@ -1051,7 +1072,10 @@ vm_remove(struct vmd_vm *vm)
if (vm == NULL)
return;
+ log_debug("%s: removing vm %d from running config",
+ __func__, vm->vm_vmid);
TAILQ_REMOVE(env->vmd_vms, vm, vm_entry);
+ log_debug("%s: calling vm_stop", __func__);
vm_stop(vm, 0);
free(vm);
}
@@ -1178,6 +1202,7 @@ vm_register(struct privsep *ps, struct vmop_create_params
*vmc,
/* Assign a new internal Id if not specified */
vm->vm_vmid = id == 0 ? env->vmd_nvm : id;
+ log_debug("%s: registering vm %d", __func__, vm->vm_vmid);
TAILQ_INSERT_TAIL(env->vmd_vms, vm, vm_entry);
*ret_vm = vm;
diff --git usr.sbin/vmd/vmm.c usr.sbin/vmd/vmm.c
index 73a895f726e..d3233147cff 100644
--- usr.sbin/vmd/vmm.c
+++ usr.sbin/vmd/vmm.c
@@ -146,6 +146,7 @@ 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);
if (id == 0) {
res = ENOENT;
@@ -278,8 +279,11 @@ vmm_dispatch_parent(int fd, struct privsep_proc *p, struct
imsg *imsg)
case IMSG_VMDOP_START_VM_RESPONSE:
if (res != 0) {
/* Remove local reference if it exists */
- if ((vm = vm_getbyvmid(imsg->hdr.peerid)) != NULL)
+ if ((vm = vm_getbyvmid(imsg->hdr.peerid)) != NULL) {
+ log_debug("%s: removing vm, START_VM_RESPONSE",
+ __func__);
vm_remove(vm);
+ }
}
if (id == 0)
id = imsg->hdr.peerid;
@@ -314,6 +318,7 @@ vmm_sighdlr(int sig, short event, void *arg)
struct vmd_vm *vm;
struct vm_terminate_params vtp;
+ log_debug("%s: handling signal", __func__);
switch (sig) {
case SIGCHLD:
do {
@@ -355,6 +360,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);
} else
fatalx("unexpected cause of SIGCHLD");
@@ -381,6 +387,7 @@ vmm_shutdown(void)
/* XXX suspend or request graceful shutdown */
(void)terminate_vm(&vtp);
+ log_debug("%s: calling vm_remove", __func__);
vm_remove(vm);
}
}
@@ -465,8 +472,10 @@ vmm_dispatch_vm(int fd, short event, void *arg)
case IMSG_VMDOP_SEND_VM_RESPONSE:
IMSG_SIZE_CHECK(&imsg, &vmr);
memcpy(&vmr, imsg.data, sizeof(vmr));
- if(!vmr.vmr_result)
+ if(!vmr.vmr_result) {
+ log_debug("%s: calling vm_remove", __func__);
vm_remove(vm);
+ }
case IMSG_VMDOP_PAUSE_VM_RESPONSE:
case IMSG_VMDOP_UNPAUSE_VM_RESPONSE:
for (i = 0; i < sizeof(procs); i++) {
@@ -639,6 +648,7 @@ vmm_start_vm(struct imsg *imsg, uint32_t *id)
return (0);
err:
+ log_debug("%s: calling vm_remove", __func__);
vm_remove(vm);
return (ret);
--
2.14.1
