On Thu, Sep 07, 2017 at 04:47:52PM -0700, Carlos Cardenas wrote:
> Add log_debug statements in key places to assist with
> troubleshooting.
>
Thanks for these diffs. I committed this one. There was one line below
that had spaces instead of tabs still, but I caught it and fixed it.
I also very slightly modified some of the wording in some of the
messages.
-ml
> diff --git usr.sbin/vmd/config.c usr.sbin/vmd/config.c
> index 9ea87eb86e8..7c1eed2697a 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..5e103df08b9 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..6c5ff737471 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..f561d1039ae 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..0e5ed1ed605 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
>
