storage/callback: some callbacks added & removed

Added:
post_volume_create & post_volume_import as requested by Marek

Removed:
post_ctor as this wasn't really useful anyway, but required a lot of
sync code. Without it, some refactoring & potential async improvements
became possible.

qubes/storage/callback.json.example

@@ -9,17 +9,18 @@
         "cmd": "Default command to call when the [pre|post]_[op] operations are not specified (default: None). The command is called as such: `[cmd] [name] [bdriver] [operation] [ctor params]`. [name]: name of the pool, [operation]: any of the `[pre|post]_` operations from below including its arguments, [bdriver]: backend driver of the pool, [ctor params]: Parameters passed to the `bdriver` constructor in JSON format. Each parameter is on a single line for easy parsing.",
         "signal_back": "Boolean (true|false) to allow the executed commands to send signals back to the callback driver (default: false). Signals must be on a dedicated line on stdout. Currently only `SIGNAL_setup` is supported. When found, it causes the callback driver to re-setup the backend pool.",
         "pre_sinit": "Command to call before one-time storage initialization/first usage (default: None). Called exactly once for every `qubesd` start. Can be used to override `cmd`. Pass `-` to ignore this callback entirely even if `cmd` is specified.",
-        "post_ctor": "Command to call after object construction (default: None). Can be used to override `cmd`. Pass `-` to ignore this callback entirely even if `cmd` is specified.",
+        "pre_setup": "Called before creating a new pool. Can be used to override `cmd`. Pass `-` to ignore this callback entirely even if `cmd` is specified.",
-        "pre_setup": "Called before creation of a new pool. Same as above otherwise.",
+        "post_destroy": "Called after removing an existing pool. Same as above otherwise.",
-        "post_destroy": "Called after removal of an existing pool. Same as above otherwise.",
+        "pre_volume_create": "Called before creating a volume for the pool. Same as above otherwise.",
-        "pre_volume_create": "Called before creation of a volume for the pool. Same as above otherwise.",
+        "post_volume_create": "Called after creating a volume for the pool. Same as above otherwise.",
-        "post_volume_remove": "Called after removal of a volume of the pool. Same as above otherwise.",
+        "post_volume_remove": "Called after removing a volume of the pool. Same as above otherwise.",
         "pre_volume_resize": "Called before resizing a volume of the pool. Same as above otherwise.",
         "pre_volume_start": "Called before starting a volume of the pool. Same as above otherwise.",
         "post_volume_start": "Called after starting a volume of the pool. Same as above otherwise.",
         "post_volume_stop": "Called after stopping a volume of the pool. Same as above otherwise.",
-        "pre_volume_import": "Called before importing a volume from elsewhere. Same as above otherwise.",
+        "pre_volume_import": "Called before importing a volume from another. Same as above otherwise.",
-        "pre_volume_import_data": "Called before importing a volume from elsewhere. Same as above otherwise.",
+        "post_volume_import": "Called after importing a volume from another. Same as above otherwise.",
+        "pre_volume_import_data": "Called before overwriting this volume with new data. Same as above otherwise.",
         "post_volume_import_data_end": "Called after finishing an `import_data` action. Same as above otherwise.",
         "pre_volume_export": "Called before exporting a volume. Same as above otherwise.",
         "post_volume_export_end": "Called after a volume export completed. Same as above otherwise.",
@@ -59,7 +60,6 @@
             "dir_path": "/mnt/test03"
         },
         "cmd": "exit 1",
-        "post_ctor": "testCbLogArgs post_ctor",
         "pre_sinit": "testCbLogArgs pre_sinit",
         "pre_setup": "testCbLogArgs pre_setup",
         "post_destroy": "-",
@@ -71,7 +71,6 @@
         "bdriver_args": {
             "dir_path": "/mnt/test_luks"
         },
-        "post_ctor": "logger 'testing-succ-file-luks: ctor'",
         "pre_setup": "set -e -o pipefail ; [ ! -e /mnt/test.key ] ; [ ! -e /mnt/test.luks ] ; dd if=/dev/random bs=100 of=/mnt/test.key iflag=fullblock count=1 ; dd if=/dev/urandom bs=1M of=/mnt/test.luks iflag=fullblock count=2048 ; cryptsetup luksFormat -q --key-file /mnt/test.key /mnt/test.luks ; cryptsetup open -q --key-file /mnt/test.key /mnt/test.luks test-luks ; mkfs -t ext4 /dev/mapper/test-luks ; mkdir -p /mnt/test_luks ; mount /dev/mapper/test-luks /mnt/test_luks",
         "pre_sinit": "set -e -o pipefail ; if [[ \"$(findmnt -S /dev/mapper/test-luks -n -o TARGET)\" != \"/mnt/test_luks\" ]] ; then cryptsetup status test-luks > /dev/null || cryptsetup open -q --key-file /mnt/test.key /mnt/test.luks test-luks ; mount /dev/mapper/test-luks /mnt/test_luks ; else exit 0 ; fi",
         "post_destroy": "umount /mnt/test_luks && cryptsetup close test-luks ; set -e -o pipefail ; dd if=/dev/urandom bs=100 of=/mnt/test.key iflag=fullblock count=1 ; rm -f /mnt/test.key ; rm -f /mnt/test.luks ; rmdir /mnt/test_luks",

qubes/storage/callback.py

@@ -23,6 +23,7 @@ import logging
 import subprocess
 import json
 import asyncio
+import locale
 from shlex import quote
 from qubes.utils import coro_maybe
 
@@ -77,9 +78,9 @@ class CallbackPool(qubes.storage.Pool):
     qvm-pool -o conf_id=testing-succ-file-02 -a test callback
     qvm-pool
     ls /mnt/test02
-    less /tmp/callback.log (post_ctor & pre_setup should be there and in that order)
+    less /tmp/callback.log (pre_setup should be there and in that order)
     qvm-create -l red -P test test-vm
-    cat /tmp/callback.log (2x pre_volume_create should be added)
+    cat /tmp/callback.log (2x pre_volume_create + 2x post_volume_create should be added)
     qvm-start test-vm
     qvm-volume | grep test-vm
     grep test-vm /var/lib/qubes/qubes.xml
@@ -88,7 +89,7 @@ class CallbackPool(qubes.storage.Pool):
     qvm-shutdown test-vm
     cat /tmp/callback.log (2x post_volume_stop should be added)
     #reboot
-    cat /tmp/callback.log (only (!) post_ctor should be there)
+    cat /tmp/callback.log (nothing (!) should be there)
     qvm-start test-vm
     cat /tmp/callback.log (pre_sinit & 2x pre_volume_start & 2x post_volume_start should be added)
     qvm-shutdown --wait test-vm && qvm-remove test-vm
@@ -110,7 +111,7 @@ class CallbackPool(qubes.storage.Pool):
     qvm-pool -o conf_id=testing-succ-file-03 -a test callback
     qvm-pool
     ls /mnt/test03
-    less /tmp/callback.log (post_ctor & pre_setup should be there, no more arguments)
+    less /tmp/callback.log (pre_setup should be there, no more arguments)
     qvm-pool -r test && sudo rm -rf /mnt/test03
     less /tmp/callback.log (nothing should have been added)
 
@@ -239,7 +240,6 @@ class CallbackPool(qubes.storage.Pool):
 
         super().__init__(name=name, revisions_to_keep=int(bdriver_args.get('revisions_to_keep', 1)))
         self._cb_ctor_done = True
-        self._callback_nocoro('post_ctor')
 
     def _check_init(self):
         ''' Whether or not this object requires late storage initialization via callback. '''
@@ -264,14 +264,13 @@ class CallbackPool(qubes.storage.Pool):
         if self._cb_requires_init:
             yield from self._init(**kwargs)
 
-    def _callback_nocoro(self, cb, cb_args=None, handle_signals=True):
+    @asyncio.coroutine
-        '''Run a callback (variant that can be used outside of coroutines / from synchronous code).
+    def _callback(self, cb, cb_args=None):
+        '''Run a callback.
         :param cb: Callback identifier string.
         :param cb_args: Optional list of arguments to pass to the command as last arguments.
                         Only passed on for the generic command specified as `cmd`, not for `on_xyz` callbacks.
-        :param handle_signals: Attempt to handle signals locally in synchronous code.
+        :return: Nothing.
-                        May throw an exception, if a callback signal cannot be handled locally.
-        :return: String with potentially unhandled signals, if `handle_signals` is `False`. Nothing otherwise.
         '''
         if self._cb_ctor_done:
             cmd = self._cb_conf.get(cb)
@@ -285,27 +284,18 @@ class CallbackPool(qubes.storage.Pool):
                 args = ' '.join(quote(str(a)) for a in args)
                 cmd = ' '.join(filter(None, [cmd, args]))
                 self._cb_log.info('callback driver executing (%s, %s %s): %s', self._cb_conf_id, cb, cb_args, cmd)
-                res = subprocess.run(['/bin/bash', '-c', cmd], check=True, stdout=subprocess.PIPE, stderr=subprocess.PIPE, universal_newlines=True)
+                cmd_arr = ['/bin/bash', '-c', cmd]
-                #stdout & stderr are reported if the exit code check fails
+                proc = yield from asyncio.create_subprocess_exec(*cmd_arr, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
-                self._cb_log.debug('callback driver stdout (%s, %s %s): %s', self._cb_conf_id, cb, cb_args, res.stdout)
+                stdout, stderr = yield from proc.communicate()
-                self._cb_log.debug('callback driver stderr (%s, %s %s): %s', self._cb_conf_id, cb, cb_args, res.stderr)
+                encoding = locale.getpreferredencoding()
+                stdout = stdout.decode(encoding)
+                stderr = stderr.decode(encoding)
+                if proc.returncode != 0:
+                    raise subprocess.CalledProcessError(returncode=proc.returncode, cmd=cmd, output=stdout, stderr=stderr)
+                self._cb_log.debug('callback driver stdout (%s, %s %s): %s', self._cb_conf_id, cb, cb_args, stdout)
+                self._cb_log.debug('callback driver stderr (%s, %s %s): %s', self._cb_conf_id, cb, cb_args, stderr)
                 if self._cb_conf.get('signal_back', False) is True:
-                    if handle_signals:
+                        yield from self._process_signals(stdout)
-                        self._process_signals_nocoro(res.stdout)
-                    else:
-                        return res.stdout
-        return None
-
-    @asyncio.coroutine
-    def _callback(self, cb, cb_args=None):
-        '''Run a callback.
-        :param cb: Callback identifier string.
-        :param cb_args: Optional list of arguments to pass to the command as last arguments.
-                        Only passed on for the generic command specified as `cmd`, not for `on_xyz` callbacks.
-        '''
-        ret = self._callback_nocoro(cb, cb_args=cb_args, handle_signals=False)
-        if ret:
-            yield from self._process_signals(ret)
 
     @asyncio.coroutine
     def _process_signals(self, out):
@@ -319,16 +309,6 @@ class CallbackPool(qubes.storage.Pool):
                 #NOTE: calling our own methods may lead to a deadlock / qubesd freeze due to `self._assert_initialized()` / `self._cb_init_lock`
                 yield from coro_maybe(self._cb_impl.setup())
 
-    def _process_signals_nocoro(self, out):
-        '''Variant of `process_signals` to be used with synchronous code.
-        :param out: String to check for signals. Each signal must be on a dedicated line.
-                    They are executed in the order they are found. Callbacks are not triggered.
-        :raise UnhandledSignalException: If signals cannot be handled here / in synchronous code.
-        '''
-        for line in out.splitlines():
-            if line == 'SIGNAL_setup':
-                raise UnhandledSignalException(self, line)
-
     @property
     def backend_class(self):
         '''Class of the first non-CallbackPool backend Pool.'''
@@ -477,7 +457,9 @@ class CallbackVolume(qubes.storage.Volume):
     def create(self):
         yield from self._assert_initialized()
         yield from self._callback('pre_volume_create')
-        return (yield from coro_maybe(self._cb_impl.create()))
+        ret = yield from coro_maybe(self._cb_impl.create())
+        yield from self._callback('post_volume_create')
+        return ret
 
     @asyncio.coroutine
     def remove(self):
@@ -524,7 +506,9 @@ class CallbackVolume(qubes.storage.Volume):
     def import_volume(self, src_volume):
         yield from self._assert_initialized()
         yield from self._callback('pre_volume_import', cb_args=[src_volume.vid])
-        return (yield from coro_maybe(self._cb_impl.import_volume(src_volume)))
+        ret = yield from coro_maybe(self._cb_impl.import_volume(src_volume))
+        yield from self._callback('post_volume_import', cb_args=[src_volume.vid])
+        return ret
 
     def is_dirty(self):
         # pylint: disable=protected-access

qubes/tests/storage_callback.py

@@ -58,10 +58,10 @@ CB_DATA = {'utest-callback-01': {
                      'thin_pool':    qubes.tests.storage_lvm.DEFAULT_LVM_POOL.split('/')[1]
                 },
                 'cmd': 'exit 1',
-                'post_ctor': LOG_BIN + ' post_ctor',
                 'pre_sinit': LOG_BIN + ' pre_sinit',
                 'pre_setup': LOG_BIN + ' pre_setup',
                 'pre_volume_create': LOG_BIN + ' pre_volume_create',
+                'post_volume_create': LOG_BIN + ' post_volume_create',
                 'pre_volume_import_data': LOG_BIN + ' pre_volume_import_data',
                 'post_volume_import_data_end': LOG_BIN + ' post_volume_import_data_end',
                 'post_volume_remove': LOG_BIN + ' post_volume_remove',
@@ -299,10 +299,10 @@ class TC_91_CallbackPool(LoggingCallbackBase, qubes.tests.storage_lvm.ThinPoolBa
         vsize = 2 * qubes.config.defaults['root_img_size']
         log_expected = \
             {str(cls) + 'test_001_callbacks':
-                {0: '1: {0}\n2: {1}\n3: post_ctor\n4: {2}'.format(name, bdriver, ctor_params),
+                {0: '',
                  1: '',
                  2: '',
-                 3: '1: {0}\n2: {1}\n3: pre_sinit\n4: {2}\n1: {0}\n2: {1}\n3: pre_volume_create\n4: {2}\n5: {3}\n6: {4}\n7: None'.format(name, bdriver, ctor_params, vname, vid),
+                 3: '1: {0}\n2: {1}\n3: pre_sinit\n4: {2}\n1: {0}\n2: {1}\n3: pre_volume_create\n4: {2}\n5: {3}\n6: {4}\n7: None\n1: {0}\n2: {1}\n3: post_volume_create\n4: {2}\n5: {3}\n6: {4}\n7: None'.format(name, bdriver, ctor_params, vname, vid),
                  4: '1: {0}\n2: {1}\n3: pre_volume_import_data\n4: {2}\n5: {3}\n6: {4}\n7: None\n8: {5}'.format(name, bdriver, ctor_params, vname, vid, vsize),
                  5: '1: {0}\n2: {1}\n3: post_volume_import_data_end\n4: {2}\n5: {3}\n6: {4}\n7: None\n8: {5}'.format(name, bdriver, ctor_params, vname, vid, True),
                  6: '1: {0}\n2: {1}\n3: post_volume_remove\n4: {2}\n5: {3}\n6: {4}\n7: None'.format(name, bdriver, ctor_params, vname, vid),
@@ -320,10 +320,10 @@ class TC_92_CallbackPool(LoggingCallbackBase, qubes.tests.storage_lvm.ThinPoolBa
     def setUpClass(cls):
         log_expected = \
             {str(cls) + 'test_001_callbacks':
-                {0: '1: post_ctor',
+                {0: '',
                  1: '',
                  2: '',
-                 3: '1: pre_sinit\n1: pre_volume_create',
+                 3: '1: pre_sinit\n1: pre_volume_create\n1: post_volume_create',
                  4: '1: pre_volume_import_data',
                  5: '1: post_volume_import_data_end',
                  6: '1: post_volume_remove',