WIP: debug non-working inject-nmi

Debugging in progress, trying to find root cause of the issue mentioned in [1].

Findings:

  - `virsh inject-nmi` called directly on machine from check-machines (bypasing javascript) **works fine**
  - with recent changes, the flow reaches cockpit.spawn() reliably (logging proves that)

To simplify debugging, following temporar changes are made:

  - the `onSendNMI()` on-click handler calls LIBVIRT_PROVIDER.SENDNMI_VM() directly - to bypass redux middleware
  - to demonstrate the issue, I replaced `virsh` call by simple `touch` command (see SENDNMI_VM() in libvirt.es6)
    - cockpit.spawn() call is reached (based on logging)
    - the `touch` is not actually executed. **Why??**

`window.debugging='all'` is set (config.es6), showing that cockpit.spawn() hangs
    - `send control` is passed
    - no `recv control` is received

In addition to the hardcoded call simplification made just for debugging, I've further simplified middleware code around getVirtProvider() - no need for such complexity after avoiding external provider API.

[1] #6722

pkg/machines/config.es6

@@ -35,7 +35,17 @@ const VMS_CONFIG = {
         }
     },
     // TODO: make it configurable via config file
-    isDev: false, // Never commit with 'true'
+    isDev: true, // Never commit with 'true'
 };
 
+if (VMS_CONFIG.isDev) {
+    console.log('Turning on debug logging');
+
+    window.debugging = 'all';
+    window.addEventListener("error", function (e) {
+        console.log("---------- Error event received: " + JSON.stringify(e));
+        return false;
+    });
+}
+
 export default VMS_CONFIG;

pkg/machines/hostvmslist.jsx

@@ -28,6 +28,7 @@ import VmDisksTab from './vmdiskstab.jsx';
 import GraphicsConsole from './components/graphicsConsole.jsx';
 import { deleteDialog } from "./components/deleteDialog.jsx";
 
+import LIBVIRT_PROVIDER from './libvirt.es6'; // JUST FOR DEBUGGING!
 const _ = cockpit.gettext;
 
 function mouseClick(fun) {
@@ -71,7 +72,7 @@ const VmActions = ({ vm, config, dispatch, onStart, onReboot, onForceReboot, onS
 
     let shutdown = null;
     if (config.provider.canShutdown(state)) {
-	let buttons = [{
+        let buttons = [{
             title: _("Shut Down"),
             action: onShutdown,
             id: `${id}-off`
@@ -87,7 +88,7 @@ const VmActions = ({ vm, config, dispatch, onStart, onReboot, onForceReboot, onS
                 id: `${id}-sendNMI`
             })
         }
-        shutdown = DropdownButtons({ buttons: buttons });
+        shutdown = DropdownButtons({buttons: buttons});
     }
 
     let run = null;
@@ -482,9 +483,14 @@ const HostVmsList = ({ vms, config, dispatch }) => {
                         onForceReboot={() => dispatch(forceRebootVm(vm))}
                         onShutdown={() => dispatch(shutdownVm(vm))}
                         onForceoff={() => dispatch(forceVmOff(vm))}
+                        onSendNMI_original={() => {dispatch(sendNMI(vm))}}
+                        onSendNMI={() => { // TODO: this is for debuging only - to simplify the call to bare minimum. Still not working
+                            console.log('---- hardcoded NMI call');
+                            LIBVIRT_PROVIDER.SENDNMI_VM({ name: vm.name, connectionName: vm.connectionName})(dispatch);
+                            // dispatch(sendNMI(vm))
+                        }}
                         onUsageStartPolling={() => dispatch(usageStartPolling(vm))}
                         onUsageStopPolling={() => dispatch(usageStopPolling(vm))}
-                        onSendNMI={() => dispatch(sendNMI(vm))}
                         dispatch={dispatch}
                     />);
             })}

pkg/machines/libvirt.es6

@@ -1,4 +1,5 @@
 /*jshint esversion: 6 */
+/*jshint esversion: 6 */
 /*
  * This file is part of Cockpit.
  *
@@ -118,17 +119,18 @@ LIBVIRT_PROVIDER = {
      * @param VM name
      * @returns {Function}
      */
-    GET_VM ({ lookupId: name, connectionName }) {
-        logDebug(`${this.name}.GET_VM()`);
+    GET_VM ({ lookupId, connectionName }) {
+        logDebug(`${this.name}.GET_VM(): lookupId = '${lookupId}', connectionname = '${connectionName}'`);
 
         return dispatch => {
-            if (!isEmpty(name)) {
-                return spawnVirshReadOnly({connectionName, method: 'dumpxml', name}).then(domXml => {
+            if (!isEmpty(lookupId)) {
+                return spawnVirshReadOnly({connectionName, method: 'dumpxml', name: lookupId}).then(domXml => {
                     parseDumpxml(dispatch, connectionName, domXml);
-                    return spawnVirshReadOnly({connectionName, method: 'dominfo', name});
-                }).then(domInfo => {
-                    parseDominfo(dispatch, connectionName, name, domInfo);
-                }); // end of GET_VM return
+                    return spawnVirshReadOnly({connectionName, method: 'dominfo', name: lookupId})
+                        .then(domInfo => {
+                            parseDominfo(dispatch, connectionName, lookupId, domInfo);
+                        });
+                });
             }
         };
     },
@@ -149,14 +151,14 @@ LIBVIRT_PROVIDER = {
 
         return dispatch => { // for all connections
             return cockpit.user().done( loggedUser => {
-                const promises = Object.getOwnPropertyNames(VMS_CONFIG.Virsh.connections)
+                Object.getOwnPropertyNames(VMS_CONFIG.Virsh.connections)
                     .filter(
                         // The 'root' user does not have its own qemu:///session just qemu:///system
                         // https://bugzilla.redhat.com/show_bug.cgi?id=1045069
                         connectionName => canLoggedUserConnectSession(connectionName, loggedUser))
-                    .map(connectionName => dispatch(getAllVms(connectionName)));
-
-                return cockpit.all(promises);
+                    .forEach(connectionName =>
+                        dispatch(getAllVms(connectionName))
+                    );
             });
         };
     },
@@ -239,10 +241,10 @@ LIBVIRT_PROVIDER = {
 
     USAGE_START_POLLING ({ name, connectionName }) {
         logDebug(`${this.name}.USAGE_START_POLLING(${name}):`);
-        return (dispatch => {
+        return dispatch => {
             dispatch(updateVm({ connectionName, name, usagePolling: true}));
             dispatch(doUsagePolling(name, connectionName));
-        });
+        };
     },
 
     USAGE_STOP_POLLING ({ name, connectionName }) {
@@ -269,12 +271,61 @@ LIBVIRT_PROVIDER = {
     },
 
     SENDNMI_VM ({ name, connectionName }) {
-        logDebug(`${this.name}.SENDNMI_VM(${name}):`);
+        logDebug(`${this.name}.SENDNMI_VM(${name}) called`);
+        return dispatch => {
+            console.log('-- SENDNMI_VM before cockpit.spawn');
+
+            // Just for debuging
+            // TODO: Following 'touch' is never executed. Why??
+            cockpit.spawn(['touch', '/tmp/touch_succeeded'], {
+                    'err': 'message',
+                    'pty': true,
+                    environ: ['LC_ALL=C', 'VIRSH_DEBUG=0']
+                })
+                .always(() => { // This is never called
+                    console.log('-- touch always');
+                })
+                .stream(data => {
+                    console.log('-- touch stream(): ', data);
+                })
+                .fail(ex => {
+                    console.log('-- touch fail: ', ex);
+                });
+/*
+            // TODO: for debugging only - simplify `virsh` call to bare minimum. It's not executed
+            cockpit.spawn(['virsh'].concat(VMS_CONFIG.Virsh.connections[connectionName].params).concat(['inject-nmi', name, '--echo']), {
+                    'err': 'message',
+                    'pty': true,
+                    environ: ['LC_ALL=C', 'VIRSH_DEBUG=0']
+                })
+                .always(() => {
+                    console.log('-- nmi always');
+                })
+                .stream(data => {
+                    console.log('-- nmi stream(): ', data);
+                })
+                .fail(ex => {
+                    console.log('-- nmi fail: ', ex);
+                });
+*/
+            console.log('-- after cockpit.spawn()');
+        };
+/*
+                return dispatch => cockpit.spawn(['virsh'].concat(VMS_CONFIG.Virsh.connections[connectionName].params).concat(['inject-nmi', name]), {'err': 'message', 'pty': true})
+                    .stream(data => {
+                        console.log('-- nmi stream(): ', data);
+                    })
+                    .fail(ex => {
+                        console.log('-- nmi fail: ', ex);
+                    });
+*/
+/*
         return dispatch => spawnVirsh({connectionName,
             method: 'SENDNMI_VM',
-            failHandler: buildFailHandler({ dispatch, name, connectionName, message: _("VM SEND Non-Maskable Interrrupt action failed")}),
-            args: ['inject-nmi', name]
+            failHandler: buildFailHandler({ dispatch, name, connectionName, message: _("VM SEND Non-Maskable Interrupt action failed")}),
+            args: ['Xinject-nmi', name]
         });
+*/
     }
 };
 
@@ -285,20 +336,22 @@ function canLoggedUserConnectSession (connectionName, loggedUser) {
 function doGetAllVms (dispatch, connectionName) {
     const connection = VMS_CONFIG.Virsh.connections[connectionName];
 
-    return spawnScript({
+    spawnScript({
         script: `virsh ${connection.params.join(' ')} -r list --all | awk '$1 == "-" || $1+0 > 0 { print $2 }'`
     }).then(output => {
-        const vmNames = output.trim().split(/\r?\n/);
-        vmNames.forEach((vmName, index) => {
-            vmNames[index] = vmName.trim();
-        });
-        logDebug(`GET_ALL_VMS: vmNames: ${JSON.stringify(vmNames)}`);
+        let vmNames = output.trim().split(/\r?\n/);
+        vmNames = vmNames
+            .map(vmName => vmName.trim())
+            .filter(vmName => !!vmName); // non-empty
+
+        logDebug(`GET_ALL_VMS(connectionName='${connectionName}'): vmNames: ${JSON.stringify(vmNames)}`);
 
         // remove undefined domains
         dispatch(deleteUnlistedVMs(connectionName, vmNames));
 
         // read VM details
-        return cockpit.all(vmNames.map((name) => dispatch(getVm(connectionName, name))));
+        // return cockpit.all(vmNames.map((name) => dispatch(getVm(connectionName, name))));
+        vmNames.forEach(name => dispatch(getVm(connectionName, name)));
     });
 }
 

pkg/machines/provider.es6

@@ -28,27 +28,29 @@ import Store from './store.es6';
 import { Listing, ListingRow } from "cockpit-components-listing.jsx";
 import { StateIcon, DropdownButtons } from './hostvmslist.jsx';
 
-var provider = null;
-
+let provider = null;
 export function setVirtProvider (prov) {
     provider = prov;
 }
 
-function getVirtProvider (store) {
-    const state = store.getState();
-    if (state.config.provider) {
-        return cockpit.resolve(state.config.provider);
+function getVirtProvider ({ dispatch, getState }) {
+    const initializedProvider = getState().config.provider;
+    if (initializedProvider) {
+        logDebug('Resolving getVirtProvider with known provider: ', JSON.stringify(initializedProvider));
+        return initializedProvider;
+        // return cockpit.resolve(initializedProvider);
     } else {
-        const deferred = cockpit.defer();
         logDebug('Discovering provider');
 
+        const deferred = cockpit.defer();
         if (!provider) { //  no provider available
+            console.error('getVirtProvider() no provider detected!');
             deferred.reject();
         } else {
             if (!provider.init) {
                 // Skip the initialization if provider does not define the `init` hook.
                 logDebug('No init() method in the provider');
-                store.dispatch(setProvider(provider));
+                dispatch(setProvider(provider));
                 deferred.resolve(provider);
             } else {
                 // The external provider plugin lives in the same context as the parent code, so it should be shared.
@@ -59,16 +61,16 @@ function getVirtProvider (store) {
                 if (initResult && initResult.then) { // if Promise or $.jqXHR, the then() is defined
                     initResult.then(() => {
                         logDebug(`Provider's Init() is returning resolved Promise`);
-                        store.dispatch(setProvider(provider));
+                        dispatch(setProvider(provider));
                         deferred.resolve(provider);
                     }, (ex) => {
-                        logDebug(`Provider's Init() is returning rejected Promise`);
+                        console.info(`Provider's Init() is returning rejected Promise`);
                         deferred.reject(ex);
                     });
                 } else { // Promise is not returned, so at least 'true' is expected
                     if (initResult) {
                         logDebug(`No Promise returned, but successful init: ${JSON.stringify(initResult)}`);
-                        store.dispatch(setProvider(provider));
+                        dispatch(setProvider(provider));
                         deferred.resolve(provider);
                     } else {
                         deferred.reject();
@@ -87,18 +89,35 @@ function getVirtProvider (store) {
  * Lazily initializes the virt provider and dispatches given method on it.
  */
 export function virt(method, action) {
-    return (dispatch, getState) => getVirtProvider({dispatch, getState}).fail(err => {
-        console.error('could not detect any virt provider');
-    }).then(provider => {
+    logDebug(`virt() method called: "${method}", action: ${JSON.stringify(action)}`);
+
+    function callVirtFunction(dispatch, provider, method, action) {
+        console.log(`callVirtFunction() called for method: ${method}`);
         if (method in provider) {
             logDebug(`Calling ${provider.name}.${method}`, action);
             return dispatch(provider[method](action));
         } else {
-            var msg = `method: '${method}' is not supported by provider: '${provider.name}'`;
+            const msg = `method: '${method}' is not supported by provider: '${provider.name}'`;
             console.warn(msg);
             return cockpit.reject(msg);
         }
-    });
+    }
+
+    return (dispatch, getState) => {
+        const virtProvider = getVirtProvider({ dispatch, getState });
+
+        if (virtProvider.name) { // already initialized provider
+            return callVirtFunction(dispatch, provider, method, action);
+        } else { // Promise
+            return virtProvider
+                .fail(err => {
+                    console.error('Could not detect any virt provider');
+                })
+                .then(provider => {
+                    return callVirtFunction(dispatch, provider, method, action);
+                });
+        }
+    };
 }
 
 /**

pkg/machines/services.es6

@@ -27,6 +27,7 @@ export function spawnProcess({ cmd, args = [], stdin, failHandler }) {
     return spawn(cockpit.spawn(spawnArgs, { err: "message", environ: ['LC_ALL=C'] })
         .input(stdin))
         .fail((exception, data) => {
+            logDebug('spawnProcess() fail: ', cmd, ', ', exception, ',', data);
             if (failHandler) {
                 return failHandler({exception, data, spawnArgs});
             }
@@ -51,9 +52,11 @@ function spawn(command) {
             stdout += chunk;
         })
         .done(() => {
+            logDebug('spawn done');
             deferred.resolve(stdout);
         })
         .fail((ex, data) => {
+            logDebug('spawn failed');
             deferred.reject(ex, data, stdout);
         });
 

test/verify/check-machines

@@ -223,6 +223,23 @@ class TestMachines(MachineCase):
         emulated_machine = b.eval_js("$('#vm-subVmTest1-emulatedmachine').text()")
         self.assertTrue(len(emulated_machine) > 0) # emulated machine varies across test machines
 
+        # DEBUG ONLY: Following NMI-related code must go before the 'shut off' scenario bellow.
+        # It's moved here just for debugging purpose to simplify test scenario
+        print("------------ About to test NMI")
+        # Send Non-Maskable Interrupt (no change in VM state is expected)
+        b.click("#vm-subVmTest1-off-caret")
+        b.wait_visible("#vm-subVmTest1-sendNMI")
+        b.click("#vm-subVmTest1-sendNMI")
+        b.wait_not_visible("#vm-subVmTest1-sendNMI")
+
+        # but this works fine: print self.machine.execute("virsh -c qemu:///system inject-nmi subVmTest1")
+        print("----------- About to wait for logs")
+        # It requires another sequential virt call before it prints anything about an NMI,
+        # so receiving NMI call validation is done here, after shutting off the VM
+        if args["logfile"] is not None:
+            wait(lambda: "NMI received" in self.machine.execute("cat {0}".format(args["logfile"])))
+        print("----------- NMI found in logs")
+
         # switch to and check Usage
         b.wait_present("#vm-subVmTest1-usage")
         b.click("#vm-subVmTest1-usage")
@@ -250,23 +267,12 @@ class TestMachines(MachineCase):
         if args["logfile"] is not None:
             wait(lambda: "login as 'cirros' user." in self.machine.execute("cat {0}".format(args["logfile"])), delay=3)
 
-        # Send Non-Maskable Interrupt (no change in VM state is expected)
-        b.click("#vm-subVmTest1-off-caret")
-        b.wait_visible("#vm-subVmTest1-sendNMI")
-        b.click("#vm-subVmTest1-sendNMI")
-        b.wait_not_visible("#vm-subVmTest1-sendNMI")
-
         # shut off
         b.click("#vm-subVmTest1-off-caret")
         b.wait_visible("#vm-subVmTest1-forceOff")
         b.click("#vm-subVmTest1-forceOff")
         b.wait_in_text("#vm-subVmTest1-state", "shut off")
 
-        # It requires another sequential virt call before it prints anything about an NMI,
-        # so receiving NMI call validation is done here, after shutting off the VM
-        if args["logfile"] is not None:
-            wait(lambda: "NMI received" in self.machine.execute("cat {0}".format(args["logfile"])))
-
         # continue shut off validation - usage should drop to zero
         b.wait_in_text("#chart-donut-0 .donut-title-big-pf", "0.00")
         b.wait_in_text("#chart-donut-1 .donut-title-big-pf", "0.0")