vmadmd

foo.diff

diff --git a/src/vm/node_modules/zoneevent.js b/src/vm/node_modules/zoneevent.js
index 16742cb..b221007 100644
--- a/src/vm/node_modules/zoneevent.js
+++ b/src/vm/node_modules/zoneevent.js
@@ -117,6 +117,9 @@ ZoneEvent.prototype._handleVmadmEvent = function _handleVmadmEvent(ev) {
 
     switch (ev.type) {
     case 'create':
+        assert.object(ev.vm, 'ev.vm');
+        assert.string(ev.vm.zone_state, 'ev.vm.zone_state');
+
         obj.oldstate = '';
         obj.newstate = ev.vm.zone_state;
         zoneupdated = true;
@@ -155,7 +158,7 @@ ZoneEvent.prototype._handleVmadmEvent = function _handleVmadmEvent(ev) {
         if (obj.oldstate === 'installed') {
             obj.oldstate = 'uninitialized';
         }
-        self.emit('event', obj);
+        self.emit('event', obj, ev.vm);
     }
 };
 
diff --git a/src/vm/sbin/vmadmd.js b/src/vm/sbin/vmadmd.js
index 0e47ed9..4222aac 100755
--- a/src/vm/sbin/vmadmd.js
+++ b/src/vm/sbin/vmadmd.js
@@ -38,6 +38,7 @@ var VM = require('/usr/vm/node_modules/VM');
 var onlyif = require('/usr/node/node_modules/onlyif');
 var path = require('path');
 var http = require('http');
+var Queue = require('/usr/vm/node_modules/queue').Queue;
 var Qmp = require('/usr/vm/node_modules/qmp').Qmp;
 var qs = require('querystring');
 var url = require('url');
@@ -85,6 +86,8 @@ var seen_vms = {};
 // Used for reporting state changes (running/stopped) to interested listeners
 var stateReporter = new EventEmitter();
 
+// Zone Event serialization queue
+var zoneEventQueue;
 
 function sysinfo(callback)
 {
@@ -883,20 +886,28 @@ function stateWaiter(vmUuid, state, opts, callback) {
     }, 30000);
 }
 
-// NOTE: nobody's paying attention to whether this completes or not.
-function updateZoneStatus(ev)
+function updateZoneStatus(opts, callback)
 {
-    var load_fields;
     var reprovisioning = false;
 
+    assert.object(opts, 'opts');
+    assert.object(opts.ev, 'opts.ev');
+    assert.object(opts.vmobj, 'opts.vmobj');
+    assert.func(callback, 'callback');
+
+    var ev = opts.ev;
+    var vmobj = opts.vmobj;
+
+    log.trace({ev: ev}, 'updateZoneStatus called');
+
     if (! ev.hasOwnProperty('zonename') || ! ev.hasOwnProperty('oldstate')
         || ! ev.hasOwnProperty('newstate') || ! ev.hasOwnProperty('date')) {
 
-        log.debug('skipping unknown event: ' + JSON.stringify(ev, null, 2));
+        log.debug({ev: ev}, 'skipping unknown event');
+        callback();
         return;
     }
 
-
     /*
      * With OS-4942 and OS-5011 additional states were added which occur before
      * the zone is installed. We don't care about such zones here since we're
@@ -909,6 +920,14 @@ function updateZoneStatus(ev)
         // just log it
         log.debug({old: ev.oldstate, new: ev.newstate},
             'ignoring state transitions before first boot');
+        callback();
+        return;
+    }
+
+    // never do anything to failed zones
+    if (vmobj.failed) {
+        log.info('doing nothing for failed VM %s', ev.zonename);
+        callback();
         return;
     }
 
@@ -921,6 +940,12 @@ function updateZoneStatus(ev)
         stateReporter.emit('stopped', ev.zonename);
     }
 
+    log.debug('VM %s went from %s to %s',
+        ev.zonename, ev.oldstate, ev.newstate);
+
+    if (!seen_vms.hasOwnProperty(ev.zonename)) {
+        seen_vms[ev.zonename] = vmobj;
+    }
     /*
      * State changes we care about:
      *
@@ -942,151 +967,89 @@ function updateZoneStatus(ev)
      *    - if <zonepath>/root/var/svc/provisioning shows up check for
      *      reprovisioning
      */
-
-    // if we've never seen this VM before, we always load once.
-    if (!seen_vms.hasOwnProperty(ev.zonename)) {
-        log.debug(ev.zonename + ' is a VM we haven\'t seen before and went '
-            + 'from ' + ev.oldstate + ' to ' + ev.newstate + ' at ' + ev.date);
-        seen_vms[ev.zonename] = {};
-        // We'll continue on to load this VM below with VM.load()
-    } else if (!seen_vms[ev.zonename].hasOwnProperty('uuid')) {
-        // We just saw this machine and haven't finished loading it the first
-        // time.
-        log.debug('Already loading VM ' + ev.zonename + ' ignoring transition'
-            + ' from ' + ev.oldstate + ' to ' + ev.newstate + ' at ' + ev.date);
-        return;
-    } else if (PROV_WAIT[seen_vms[ev.zonename].uuid]) {
-        // We're already waiting for this machine to provision, other
-        // transitions are ignored in this state because we don't start VNC
-        // until after provisioning anyway.
-        log.debug('still waiting for ' + seen_vms[ev.zonename].uuid
-            + ' to complete provisioning, ignoring additional transition.');
-        return;
-    } else if (!(seen_vms[ev.zonename].provisioned)) {
-        log.debug('VM ' + seen_vms[ev.zonename].uuid + ' is not provisioned'
-            + ' and not provisioning, doing VM.load().');
-        // Continue on to VM.load()
-    } else if (seen_vms[ev.zonename].brand === 'kvm'
+    if (PROV_WAIT[vmobj.uuid]) {
+        /*
+         * We're already waiting for this machine to provision, other
+         * transitions are ignored in this state because we don't start VNC
+         * until after provisioning anyway.
+         */
+        log.debug('still waiting for %s to complete provisioning, '
+            + 'ignoring additional transition', vmobj.uuid);
+        callback();
+    } else if (!vmobj.provisioned) {
+        log.debug('VM %s is not provisioned and not provisioning', vmobj.uuid);
+        next();
+    } else if (vmobj.hvm
         && (ev.newstate === 'running'
         || ev.oldstate === 'running'
         || ev.newstate === 'uninitialized')) {
 
-        log.info('' + ev.zonename + ' (' +seen_vms[ev.zonename].brand
-            + ') went from ' + ev.oldstate + ' to ' + ev.newstate
-            + ' at ' + ev.when);
-        // Continue on to VM.load()
-    } else if (seen_vms[ev.zonename].docker
-        && (ev.newstate === 'uninitialized')) {
-
-        VM.load(ev.zonename, {fields: [
-            'autoboot',
-            'brand',
-            'exit_status',
-            'internal_metadata',
-            'state',
-            'uuid',
-            'zone_state',
-            'zonepath'
-        ]}, function (err, vmobj) {
-            log.info(ev.zonename + ' (docker) went from ' + ev.oldstate + ' to '
-                + ev.newstate + ' at ' + ev.date);
+        log.info('HVM %s (%s) went from %s to %s',
+            ev.zonename, vmobj.brand, ev.oldstate, ev.newstate);
+        next();
+    } else if (vmobj.docker
+        && ev.newstate === 'uninitialized') {
+
+        log.info('VM %s (docker) went from %s to %s',
+            ev.zonename, ev.oldstate, ev.newstate);
+
+        /*
+         * If we stop while autoboot is set, the user was intending for it
+         * to be up. So, if there's a restart policy we start it. If not, we
+         * leave it alone.
+         */
+        if (vmobj.autoboot
+            && vmobj.zone_state !== 'running'
+            && vmobj.internal_metadata
+            && vmobj.internal_metadata['docker:restartpolicy']) {
+
+            // Add the last_runtime field in case we should reset the delay
+            addLastRuntime(vmobj, {log: log}, function () {
+                // no callback to call when updateZoneStatus() completes,
+                // nobody cares about errors.
+                applyDockerRestartPolicy(vmobj);
+            });
+        }
+        callback();
+    } else {
+        assert.string(vmobj.zonepath, 'vmobj.zonepath');
 
-            /*
-             * If we stop while autoboot is set, the user was intending for it
-             * to be up. So, if there's a restart policy we start it. If not, we
-             * leave it alone.
-             */
-            if (vmobj.autoboot
-                && vmobj.zone_state !== 'running'
-                && vmobj.internal_metadata
-                && vmobj.internal_metadata['docker:restartpolicy']) {
-
-                // Add the last_runtime field in case we should reset the delay
-                addLastRuntime(vmobj, {log: log}, function () {
-                    // no callback to call when updateZoneStatus() completes,
-                    // nobody cares about errors.
-                    applyDockerRestartPolicy(vmobj);
-                });
-            }
-        });
+        fs.stat(util.format('%s/root/var/svc/provisioning', vmobj.zonepath),
+            function (err, stats) {
 
-        return;
-    } else {
-        try {
-            if (fs.existsSync(seen_vms[ev.zonename].zonepath
-                + '/root/var/svc/provisioning')) {
+            if (err && err.code === 'ENOENT') {
+                // File not found - not reproviosining
+                log.debug('provisioning file not found');
+            } else if (err) {
+                log.warn(err, 'Unable to check for /var/svc/provisioning for '
+                    + 'VM %s', vmobj.uuid);
+            } else {
+                assert(stats, 'stats');
 
-                log.info('/var/svc/provisioning exists for VM '
-                    + seen_vms[ev.zonename].uuid + ' assuming reprovisioning');
+                log.info('/var/svc/provisioning exists for VM %s, '
+                    + 'assuming reprovisioning', vmobj.uuid);
                 reprovisioning = true;
             }
-        } catch (e) {
-            if (e.code !== 'ENOENT') {
-                log.warn(e, 'Unable to check for /var/svc/provisioning for '
-                    + 'VM ' + seen_vms[ev.zonename].uuid);
+
+            if (reprovisioning) {
+                next();
+            } else {
+                log.trace('ignoring transition for %s (%s)',
+                    ev.zonename, vmobj.brand);
+                callback();
             }
-        }
-        if (!reprovisioning) {
-            log.trace('ignoring transition for ' + ev.zonename + ' ('
-                + seen_vms[ev.zonename].brand + ') from ' + ev.oldstate + ' to '
-                + ev.newstate + ' at ' + ev.date);
-            return;
-        }
+        });
     }
 
-    load_fields = [
-        'brand',
-        'docker',
-        'exit_status',
-        'failed',
-        'spice_opts',
-        'spice_password',
-        'spice_port',
-        'state',
-        'transition_expire',
-        'transition_to',
-        'uuid',
-        'vnc_password',
-        'vnc_port',
-        'zone_state',
-        'zonename',
-        'zonepath'
-    ];
-
-    // XXX won't work if ev.zonename != uuid, use lookup instead?
-    VM.load(ev.zonename, {fields: load_fields}, function (err, vmobj) {
-
-        if (err) {
-            log.warn(err, 'unable to load zone: ' + err.message);
-            return;
-        }
-
-        if (vmobj.failed) {
-            // never do anything to failed zones
-            log.info('doing nothing for ' + ev.zonename + ' transition because '
-                + ' VM is marked "failed".');
-            return;
-        }
-
-        // keep track of a few things about this zone that won't change so that
-        // we don't have to VM.load() every time.
-        if (!seen_vms.hasOwnProperty(ev.zonename)) {
-            seen_vms[ev.zonename] = {};
-        }
-        if (!seen_vms[ev.zonename].hasOwnProperty('uuid')) {
-            seen_vms[ev.zonename].uuid = vmobj.uuid;
-            seen_vms[ev.zonename].brand = vmobj.brand;
-            if (vmobj.docker) {
-                seen_vms[ev.zonename].docker = vmobj.docker;
-            }
-            seen_vms[ev.zonename].zonepath = vmobj.zonepath;
-            if (ev.newstate === 'running') {
-                // if we just saw it go running and we have an existing timer
-                // waiting to start it, kill that.
-                if (restart_waiters[vmobj.uuid]) {
-                    clearTimeout(restart_waiters[vmobj.uuid]);
-                    delete restart_waiters[vmobj.uuid];
-                }
+    function next() {
+        if (ev.newstate === 'running') {
+            /*
+             * if we just saw it go running and we have an existing timer
+             * waiting to start it, kill that.
+             */
+            if (restart_waiters[vmobj.uuid]) {
+                clearTimeout(restart_waiters[vmobj.uuid]);
+                delete restart_waiters[vmobj.uuid];
             }
         }
 
@@ -1095,6 +1058,7 @@ function updateZoneStatus(ev)
             if (PROV_WAIT.hasOwnProperty(vmobj.uuid)) {
                 log.trace('already waiting for ' + vmobj.uuid
                     + ' to leave "provisioning"');
+                callback();
                 return;
             }
 
@@ -1114,22 +1078,24 @@ function updateZoneStatus(ev)
                 if (prov_err) {
                     log.error(prov_err, 'error handling provisioning state for'
                         + ' ' + vmobj.uuid + ': ' + prov_err.message);
-                    return;
+                } else {
+                    log.debug('handleProvision() for %s returned: %s',
+                        vmobj.uuid, result);
                 }
-                log.debug('handleProvision() for ' + vmobj.uuid + ' returned: '
-                    +  result);
-                return;
+
+                callback();
             });
+            return;
         } else {
             // This zone finished provisioning some time in the past
             seen_vms[ev.zonename].provisioned = true;
         }
 
-        // don't handle transitions other than provisioning for non-kvm/bhyve
-        if (['bhyve', 'kvm'].indexOf(vmobj.brand) === -1) {
-            log.trace('doing nothing for ' + ev.zonename + ' transition '
-                + 'because brand "' + vmobj.brand
-                + '" is not "kvm" or "bhyve"');
+        // don't handle transitions other than provisioning for non-hvm
+        if (!vmobj.hvm) {
+            log.trace('doing nothing for %s because brand %s non-hvm',
+                ev.zonename, vmobj.brand);
+            callback();
             return;
         }
 
@@ -1141,31 +1107,58 @@ function updateZoneStatus(ev)
                 rotateKVMLog(vmobj.uuid);
             }
             spawnRemoteDisplay(vmobj);
-        } else if (ev.oldstate === 'running') {
+            callback();
+            return;
+        }
+
+        if (ev.oldstate === 'running') {
             if (VNC.hasOwnProperty(ev.zonename)) {
                 // VMs always have zonename === uuid, so we can remove this
                 log.info('clearing state for disappearing VM ' + ev.zonename);
                 clearVM(ev.zonename);
             }
-        } else if (ev.newstate === 'uninitialized') { // this means installed!?
+            callback();
+            return;
+        }
+
+        if (ev.newstate === 'uninitialized') { // this means installed!?
             // XXX we're running stop so it will clear the transition marker
             VM.stop(ev.zonename, {'force': true}, function (e) {
                 if (e && e.code !== 'ENOTRUNNING') {
                     log.error(e, 'stop failed');
                 }
+                callback();
             });
+            return;
         }
-    });
+
+        callback();
+    }
 }
 
-function startZoneEvent(callback)
+function startZoneEvent(func)
 {
+    assert.func(func, 'func');
+
     var ze = new ZoneEvent({
         name: 'vmadmd ZoneEvent',
         log: log
     });
-    ze.on('event', function (ev) {
-        callback(ev);
+
+    ze.on('event', function (ev, vm) {
+        var description = util.format('vmadmd ZoneEvent event: %s %s -> %s',
+            ev.zonename, ev.oldstate, ev.newstate);
+
+        zoneEventQueue.enqueue({
+            description: description,
+            func: function (extras, cb) {
+                var opts = {
+                    ev: ev,
+                    vmobj: vm
+                };
+                func(opts, cb);
+            }
+        });
     });
 }
 
@@ -2641,6 +2634,11 @@ onlyif.rootInSmartosGlobal(function (err) {
         serializers: bunyan.stdSerializers
     });
 
+    zoneEventQueue = new Queue({
+        log: log,
+        workers: 1
+    });
+
     if (err) {
         log.error(err, 'Fatal: cannot run because: ' + err.message);
         process.exit(1);