diff --git a/_testfolder/test_plugins/__init__.py b/_testfolder/test_plugins/__init__.py new file mode 100644 index 0000000000..e69de29bb2 diff --git a/src/backend/InvenTree/InvenTree/settings.py b/src/backend/InvenTree/InvenTree/settings.py index 67cf784e22..c039289b72 100644 --- a/src/backend/InvenTree/InvenTree/settings.py +++ b/src/backend/InvenTree/InvenTree/settings.py @@ -247,9 +247,6 @@ PLUGIN_RETRY = get_setting( 'INVENTREE_PLUGIN_RETRY', 'PLUGIN_RETRY', 3, typecast=int ) # How often should plugin loading be tried? -# Hash of the plugin file (will be updated on each change) -PLUGIN_FILE_HASH = '' - STATICFILES_DIRS = [] # Append directory for compiled react files if debug server is running diff --git a/src/backend/InvenTree/InvenTree/tests.py b/src/backend/InvenTree/InvenTree/tests.py index 8f5d9d4c9b..b993cbecdb 100644 --- a/src/backend/InvenTree/InvenTree/tests.py +++ b/src/backend/InvenTree/InvenTree/tests.py @@ -1298,13 +1298,15 @@ class TestSettings(InvenTreeTestCase): def test_initial_install(self): """Test if install of plugins on startup works.""" - from common.settings import set_global_setting + from common.settings import get_global_setting, set_global_setting from plugin import registry set_global_setting('PLUGIN_ON_STARTUP', True) registry.reload_plugins(full_reload=True, collect=True) - self.assertGreater(len(settings.PLUGIN_FILE_HASH), 0) + self.assertGreater( + len(get_global_setting('_PLUGIN_FILE_HASH', '', create=False)), 0 + ) set_global_setting('PLUGIN_ON_STARTUP', False) diff --git a/src/backend/InvenTree/plugin/helpers.py b/src/backend/InvenTree/plugin/helpers.py index 485f8c91b8..22cf3e2986 100644 --- a/src/backend/InvenTree/plugin/helpers.py +++ b/src/backend/InvenTree/plugin/helpers.py @@ -1,5 +1,6 @@ """Helpers for plugin app.""" +import importlib import inspect import os import pathlib @@ -107,7 +108,17 @@ def handle_error(error, do_raise: bool = True, do_log: bool = True, log_name: st def get_entrypoints(): - """Returns list for entrypoints for InvenTree plugins.""" + """Returns list for entrypoints for InvenTree plugins. + + A plugin package may have been installed or uninstalled (via pip) by this + same process since the last time entry points were scanned - e.g. when a + plugin is installed/uninstalled via the API, which triggers a registry + reload immediately afterwards. Without invalidating import caches first, + a just-removed package's entry point can still be reported (or a + just-added one missed), depending on what has already been cached for + that site-packages directory. + """ + importlib.invalidate_caches() return entry_points(group='inventree_plugins') diff --git a/src/backend/InvenTree/plugin/lease.py b/src/backend/InvenTree/plugin/lease.py new file mode 100644 index 0000000000..8f1531ceff --- /dev/null +++ b/src/backend/InvenTree/plugin/lease.py @@ -0,0 +1,113 @@ +"""A short-lived, cross-process lease built on top of InvenTreeSetting. + +Used to serialize an potentially long-running operation, +without holding a database transaction open for the duration. +""" + +import time +from datetime import datetime, timedelta +from typing import Optional + +from django.db import transaction +from django.db.utils import IntegrityError, OperationalError, ProgrammingError +from django.utils import timezone + +import structlog + +logger = structlog.get_logger('inventree') + +# How long a lease is honored for, before it is treated as abandoned +CLAIM_LEASE = timedelta(minutes=5) + + +def _parse_claim(value: str) -> Optional[datetime]: + """Parse a claim timestamp (as written by `try_acquire_lease`), if any.""" + if not value: + return None + + try: + return datetime.fromisoformat(value) + except ValueError: + return None + + +def try_acquire_lease(key: str) -> bool: + """Attempt to acquire a short-lived, cross-process lease for the given key. + + The lease is recorded as a separate '_CLAIMED_AT' setting, checked and + written under a row lock - but the lock is only held for this brief read/write, + never for the (potentially slow) work the lease protects against running twice. + A lease older than CLAIM_LEASE is treated as abandoned and may be re-acquired, + so a crashed holder does not block progress forever. + """ + from common.models import InvenTreeSetting + + claim_key = f'{key.upper()}_CLAIMED_AT' + now = timezone.now() + + try: + with transaction.atomic(): + InvenTreeSetting.objects.get_or_create( + key=claim_key, defaults={'value': ''} + ) + setting = InvenTreeSetting.objects.select_for_update().get( + key__iexact=claim_key + ) + + claimed_at = _parse_claim(setting.value) + + if claimed_at is not None and (now - claimed_at) < CLAIM_LEASE: + return False + + setting.value = now.isoformat() + setting.save() + return True + except (IntegrityError, OperationalError, ProgrammingError): + logger.debug("Could not acquire lease for '%s' - database not ready", key) + return False + + +def acquire_lease_blocking( + key: str, timeout: float = 60, poll_interval: float = 0.5 +) -> bool: + """Repeatedly attempt `try_acquire_lease` until it succeeds or `timeout` elapses. + + Callers of this are not latency-sensitive (only ever triggered by an admin + action, or a startup/reload event) - so it is preferable to wait briefly for + a concurrent holder to finish, rather than silently skipping the guarded work + the first time the lease happens to be held. + + Returns True if the lease was acquired, or False if `timeout` elapsed first. + """ + deadline = time.monotonic() + timeout + + while True: + if try_acquire_lease(key): + return True + + if time.monotonic() >= deadline: + return False + + time.sleep(poll_interval) + + +def release_lease(key: str): + """Release a lease previously acquired via `try_acquire_lease`.""" + from common.models import InvenTreeSetting + + claim_key = f'{key.upper()}_CLAIMED_AT' + + try: + with transaction.atomic(): + setting = InvenTreeSetting.objects.select_for_update().get( + key__iexact=claim_key + ) + setting.value = '' + setting.save() + except ( + IntegrityError, + OperationalError, + ProgrammingError, + InvenTreeSetting.DoesNotExist, + ): + logger.debug("Could not release lease for '%s' - database not ready", key) diff --git a/src/backend/InvenTree/plugin/registry.py b/src/backend/InvenTree/plugin/registry.py index 6ee265a8c7..8ef005b50c 100644 --- a/src/backend/InvenTree/plugin/registry.py +++ b/src/backend/InvenTree/plugin/registry.py @@ -40,6 +40,7 @@ from .helpers import ( handle_error, log_registry_error, ) +from .lease import release_lease, try_acquire_lease from .plugin import InvenTreePlugin logger = structlog.get_logger('inventree') @@ -673,14 +674,53 @@ class PluginsRegistry: self.mixin_modules = collected_mixins def install_plugin_file(self): - """Make sure all plugins are installed in the current environment.""" + """Make sure all plugins are installed in the current environment. + + The hash is only persisted *after* a successful install, never before - + the lease alone is what stops two processes from installing at once (a + process that cannot acquire it simply skips, since another one is + already handling it). Writing the hash as soon as the lease is acquired + would be a narrower window with a worse failure mode: a process killed + outright (OOM, a container stopped mid-install) between that write and + actually finishing would leave the hash pointing at content that was + never installed, and - unlike a normal exception - a hard kill does not + run `finally`, so nothing would ever revert it. The next check would + then see the hash already matches and skip forever, until the plugins + file changes again. Persisting only on success means a kill at any + point simply leaves the previous hash in place, so the next check + retries normally. + """ from plugin.installer import install_plugins_file, plugins_file_hash file_hash = plugins_file_hash() - if file_hash != settings.PLUGIN_FILE_HASH: - install_plugins_file() - settings.PLUGIN_FILE_HASH = file_hash + if file_hash is None: + return + + current_hash = get_global_setting( + '_PLUGIN_FILE_HASH', '', create=False, cache=False + ) + + if current_hash == file_hash: + return + + if not try_acquire_lease('_PLUGIN_FILE_HASH'): + return + + try: + # Re-check under the lease: another process may have already + # installed this exact change while we were waiting to acquire it + current_hash = get_global_setting( + '_PLUGIN_FILE_HASH', '', create=False, cache=False + ) + + if current_hash == file_hash: + return + + if install_plugins_file() is not False: + set_global_setting('_PLUGIN_FILE_HASH', file_hash) + finally: + release_lease('_PLUGIN_FILE_HASH') # endregion @@ -744,7 +784,7 @@ class PluginsRegistry: plg_db.save() # Save the package_name attribute to the plugin - if plg_db.package_name != package_name: + if plg_db and plg_db.package_name != package_name: plg_db.package_name = package_name plg_db.save() @@ -866,7 +906,12 @@ class PluginsRegistry: except Exception as error: # Handle the error, log it and try again if attempts == 0: - handle_error(error, log_name='init_plugins', do_raise=True) + # Record the error, but do not let it propagate - a single + # broken plugin (e.g. the 'broken_sample' test fixture, or + # any plugin that fails to initialize for real) must not + # prevent every other plugin queued after it in + # self.plugin_modules from being loaded + handle_error(error, log_name='init_plugins', do_raise=False) logger.exception( '[PLUGIN] Encountered an error with %s:\n%s', @@ -1128,11 +1173,28 @@ class PluginsRegistry: logger.exception('Failed to retrieve plugin registry hash: %s', exc) return False - if reg_hash and reg_hash != self.registry_hash: + if not reg_hash or reg_hash == self.registry_hash: + return False + + # A mismatch was observed - acquire a short-lived lease before reloading + if not try_acquire_lease('_PLUGIN_REGISTRY_HASH'): + return False + + try: + # Re-check under the lease: another process may have already reloaded + # and updated the hash while we were waiting to acquire it + reg_hash = get_global_setting( + '_PLUGIN_REGISTRY_HASH', '', create=False, cache=False + ) + + if not reg_hash or reg_hash == self.registry_hash: + return False + logger.info('Plugin registry hash has changed - reloading') self.reload_plugins(full_reload=True, force_reload=True, collect=True) return True - return False + finally: + release_lease('_PLUGIN_REGISTRY_HASH') # endregion diff --git a/src/backend/InvenTree/plugin/staticfiles.py b/src/backend/InvenTree/plugin/staticfiles.py index 7827616258..7342e4bb28 100644 --- a/src/backend/InvenTree/plugin/staticfiles.py +++ b/src/backend/InvenTree/plugin/staticfiles.py @@ -1,20 +1,42 @@ -"""Static files management for InvenTree plugins.""" +"""Static files management for InvenTree plugins. + +All of the public functions in this module read and/or write the same shared +'plugins/' static output directory tree, and are not safe to run concurrently +with each other - see inventree#12769. Each one therefore acquires +PLUGIN_STATIC_FILES_LEASE for its full duration; nothing below should touch +`staticfiles_storage` outside of a section that holds this lease. + +Everything that touches `staticfiles_storage` goes through the Storage API only +(`.save`/`.delete`/`.exists`/`.listdir`/`.open`) - STATIC_ROOT is not assumed to +be local disk, since some deployments configure a remote backend (e.g. S3), +which has no rename/move primitive and no local filesystem path to operate on +directly. +""" + +import tempfile +from pathlib import Path from django.contrib.staticfiles.storage import staticfiles_storage import structlog +from plugin.lease import acquire_lease_blocking, release_lease from plugin.registry import registry logger = structlog.get_logger('inventree') +# Only one static-file collection operation (bulk or per-plugin) may run at a time. +PLUGIN_STATIC_FILES_LEASE = '_PLUGIN_STATIC_FILES' -def clear_static_dir(path, recursive=True): + +def clear_static_dir(path: str, recursive: bool = True): """Clear the specified directory from the 'static' output directory. Arguments: path: The path to the directory to clear recursive: If True, clear the directory recursively + + Caller must already hold PLUGIN_STATIC_FILES_LEASE. """ if not staticfiles_storage.exists(path): return @@ -35,41 +57,69 @@ def clear_static_dir(path, recursive=True): logger.info('Cleared static directory: %s', path) -def collect_plugins_static_files(): - """Copy static files from all installed plugins into the static directory.""" - registry.check_reload() +def _parent_dirs(relative_paths) -> set: + """Return every directory (relative, no trailing slash) implied by a set of file paths. - logger.info('Collecting static files for all installed plugins.') + e.g. {'a/b/c.js'} -> {'a', 'a/b'} + """ + dirs = set() - for slug in registry.plugins: - copy_plugin_static_files(slug, check_reload=False) + for relative_path in relative_paths: + parts = relative_path.split('/')[:-1] + + for i in range(1, len(parts) + 1): + dirs.add('/'.join(parts[:i])) + + return dirs -def clear_plugins_static_files(): - """Clear out static files for plugins which are no longer active.""" - installed_plugins = set(registry.plugins.keys()) +def _iter_storage_files(prefix: str): + """Recursively yield paths, relative to `prefix`, of every file under a storage prefix. - path = 'plugins/' + Arguments: + prefix: The storage prefix to search under - # Check that the directory actually exists - if not staticfiles_storage.exists(path): + Yields: + Relative paths of every file under the specified prefix, with no leading slash. + """ + if not staticfiles_storage.exists(prefix): return - # Get all static files in the 'plugins' static directory - dirs, _files = staticfiles_storage.listdir('plugins/') + dirs, files = staticfiles_storage.listdir(prefix) + + yield from files for d in dirs: - # Check if the directory is a plugin directory - if d not in installed_plugins: - # Clear out the static files for this plugin - clear_static_dir(f'plugins/{d}/', recursive=True) + for relative_path in _iter_storage_files(f'{prefix}{d}/'): + yield f'{d}/{relative_path}' -def copy_plugin_static_files(slug, check_reload=True): - """Copy static files for the specified plugin.""" - if check_reload: - registry.check_reload() +def _copy_plugin_static_files(slug: str): + """Copy static files for the specified plugin. + First copies the plugin's static files into a local temporary directory, so + that a failure reading the plugin's own source files (a crash, a permission + error, a source file disappearing mid-read) is caught before anything is + written to the live destination at all. Only once that full copy has + succeeded are the files written into the live destination - one at a time, + deleting any existing file of the same name first (the storage API has no + in-place overwrite: saving over an existing name otherwise gets a + '_XXXXXXX' collision-avoidance suffix instead, which is one of the ways the + original bug corrupted the output). Files that existed at the destination + before but are not part of the new content are only removed as the final + step, so files that are not being replaced are never affected. + + This does not give the same guarantee for a file that *is* being replaced: + the delete-then-save pair for that one file is not atomic (the storage API + has no rename/replace primitive to make it so), so a write failure at that + exact moment can leave that single file transiently missing, even though + every other file keeps whatever content (old or new) it already had. This + is a large reduction in blast radius versus clearing the whole directory + up front (the original bug), and self-heals on the next successful run, + but it is not an absolute guarantee for the one in-flight file. + + Caller must already hold PLUGIN_STATIC_FILES_LEASE. + """ plugin = registry.get_plugin(slug) if not plugin: @@ -83,41 +133,136 @@ def copy_plugin_static_files(slug, check_reload=True): if not source_path.is_dir(): return - # Create prefix for the destination path destination_prefix = f'plugins/{slug}/' + previous_files = set(_iter_storage_files(destination_prefix)) - # Clear the destination path - clear_static_dir(destination_prefix) + with tempfile.TemporaryDirectory(prefix=f'inventree-plugin-{slug}-') as tmp_dir: + staging_path = Path(tmp_dir) + relative_paths = [] - items = list(source_path.glob('*')) + for item in source_path.rglob('*'): + if not item.is_file(): + continue - idx = 0 - copied = 0 + relative_path = item.relative_to(source_path).as_posix() + target = staging_path / relative_path + target.parent.mkdir(parents=True, exist_ok=True) + target.write_bytes(item.read_bytes()) - while idx < len(items): - item = items[idx] + relative_paths.append(relative_path) - idx += 1 - - if item.is_dir(): - items.extend(item.glob('*')) - continue - - if item.is_file(): - relative_path = item.relative_to(source_path) + # Deterministic order, so behaviour (and any partial-failure outcome) + # does not depend on filesystem directory iteration order + relative_paths.sort() + # Everything is readable and staged locally - now write it to the live + # destination, one file at a time + for relative_path in relative_paths: destination_path = f'{destination_prefix}{relative_path}' - with item.open('rb') as src: - staticfiles_storage.save(destination_path, src) + if staticfiles_storage.exists(destination_path): + staticfiles_storage.delete(destination_path) - logger.debug('- copied %s to %s', item, destination_path) - copied += 1 + with (staging_path / relative_path).open('rb') as content: + staticfiles_storage.save(destination_path, content) - if copied > 0: - logger.info("Copied %s static files for plugin '%s'.", copied, slug) + logger.debug('- copied %s to %s', relative_path, destination_path) + + # Remove any files that were part of the previous content but are not part + # of this one - only now that the new content is fully in place + stale_files = previous_files - set(relative_paths) + + for stale_path in stale_files: + staticfiles_storage.delete(f'{destination_prefix}{stale_path}') + + # A directory that only contained stale files is now empty, but not removed + # by the file deletions above - remove any such directories too (deepest + # first, so each is already empty by the time its own turn comes) + stale_dirs = _parent_dirs(stale_files) - _parent_dirs(relative_paths) + + for stale_dir in sorted(stale_dirs, key=lambda d: d.count('/'), reverse=True): + staticfiles_storage.delete(f'{destination_prefix}{stale_dir}/') + + if relative_paths: + logger.info( + "Copied %s static files for plugin '%s'.", len(relative_paths), slug + ) + + +def collect_plugins_static_files(): + """Copy static files from all installed plugins into the static directory.""" + registry.check_reload() + + if not acquire_lease_blocking(PLUGIN_STATIC_FILES_LEASE): + logger.error( + 'Could not acquire plugin static files lease - skipping collection' + ) + return + + try: + logger.info('Collecting static files for all installed plugins.') + + for slug in registry.plugins: + _copy_plugin_static_files(slug) + finally: + release_lease(PLUGIN_STATIC_FILES_LEASE) + + +def clear_plugins_static_files(): + """Clear out static files for plugins which are no longer active.""" + if not acquire_lease_blocking(PLUGIN_STATIC_FILES_LEASE): + logger.error('Could not acquire plugin static files lease - skipping cleanup') + return + + try: + installed_plugins = set(registry.plugins.keys()) + + path = 'plugins/' + + # Check that the directory actually exists + if not staticfiles_storage.exists(path): + return + + # Get all static files in the 'plugins' static directory + dirs, _files = staticfiles_storage.listdir('plugins/') + + for d in dirs: + # Check if the directory is a plugin directory + if d not in installed_plugins: + # Clear out the static files for this plugin + clear_static_dir(f'plugins/{d}/', recursive=True) + finally: + release_lease(PLUGIN_STATIC_FILES_LEASE) + + +def copy_plugin_static_files(slug, check_reload=True): + """Copy static files for the specified plugin.""" + if check_reload: + registry.check_reload() + + if not acquire_lease_blocking(PLUGIN_STATIC_FILES_LEASE): + logger.error( + "Could not acquire plugin static files lease - skipping collection for plugin '%s'", + slug, + ) + return + + try: + _copy_plugin_static_files(slug) + finally: + release_lease(PLUGIN_STATIC_FILES_LEASE) def clear_plugin_static_files(slug: str, recursive: bool = True): """Clear static files for the specified plugin.""" - clear_static_dir(f'plugins/{slug}/', recursive=recursive) + if not acquire_lease_blocking(PLUGIN_STATIC_FILES_LEASE): + logger.error( + "Could not acquire plugin static files lease - skipping removal for plugin '%s'", + slug, + ) + return + + try: + clear_static_dir(f'plugins/{slug}/', recursive=recursive) + finally: + release_lease(PLUGIN_STATIC_FILES_LEASE) diff --git a/src/backend/InvenTree/plugin/test_plugin.py b/src/backend/InvenTree/plugin/test_plugin.py index e4fb3ad27d..0fe4ee9569 100644 --- a/src/backend/InvenTree/plugin/test_plugin.py +++ b/src/backend/InvenTree/plugin/test_plugin.py @@ -282,6 +282,16 @@ class RegistryTests(TestQueryMixin, PluginRegistryMixin, TestCase): self.assertEqual(plg.slug, 'simple') self.assertEqual(plg.human_name, 'SimplePlugin') + # Restore the registry to its normal state. self.plugin_modules was just + # collected with INVENTREE_PLUGIN_TEST_DIR pointing at `directory` - without + # this, every subsequent reload for the rest of the test run keeps trying to + # load 'simple' (and friends) from a directory that may since have been + # deleted (see test_folder_loading), silently dropping them from + # registry.plugins the next time anything reloads the registry - while their + # PluginConfig rows (created/activated above) linger on, since they aren't + # tied to this directory at all. + registry.reload_plugins(full_reload=True, collect=True) + def test_custom_loading(self): """Test if data in custom dir is loaded correctly.""" test_dir = Path('plugin_test_dir') @@ -316,6 +326,14 @@ class RegistryTests(TestQueryMixin, PluginRegistryMixin, TestCase): @override_settings(PLUGIN_TESTING_SETUP=True) def test_package_loading(self): """Test that package distributed plugins work.""" + # Restore the registry to its normal state once this test finishes - + # otherwise self.plugin_modules keeps trying to load 'zapier' from entry + # points for the rest of the test run, well after PLUGIN_TESTING_SETUP + # has reverted to False, silently dropping it from registry.plugins the + # next time anything reloads the registry - while its PluginConfig row + # lingers on (see run_package_test for the same pattern). + self.addCleanup(registry.reload_plugins, full_reload=True, collect=True) + # Install sample package subprocess.check_output(['pip', 'install', 'inventree-zapier']) @@ -341,6 +359,11 @@ class RegistryTests(TestQueryMixin, PluginRegistryMixin, TestCase): # Reload to rediscover plugins registry.reload_plugins(full_reload=True, collect=True) + # Restore the registry to its normal state - otherwise self.plugin_modules + # keeps the (permanently broken) plugins from brokenDir for the rest of the + # test run, and every subsequent reload re-attempts (and fails) to load them. + registry.reload_plugins(full_reload=True, collect=True) + self.assertEqual(len(registry.errors), 3) errors = registry.errors @@ -562,6 +585,178 @@ class RegistryTests(TestQueryMixin, PluginRegistryMixin, TestCase): finally: registry.plugins = original_plugins + def test_lease_survives_database_not_ready(self): + """Test that the lease functions degrade gracefully if the database is not ready.""" + from django.db.utils import ProgrammingError + + from common.models import InvenTreeSetting + from plugin.lease import release_lease, try_acquire_lease + + with mock.patch.object( + InvenTreeSetting.objects, + 'get_or_create', + side_effect=ProgrammingError('relation does not exist'), + ): + self.assertFalse(try_acquire_lease('_test_lease_db_not_ready')) + + with mock.patch.object( + InvenTreeSetting.objects, + 'select_for_update', + side_effect=ProgrammingError('relation does not exist'), + ): + # Must not raise + release_lease('_test_lease_db_not_ready') + + def test_lease_acquire_release(self): + """Test that try_acquire_lease / release_lease provide mutual exclusion.""" + from plugin.lease import release_lease, try_acquire_lease + + key = '_test_lease_acquire_release' + + # First attempt succeeds + self.assertTrue(try_acquire_lease(key)) + + # A second attempt while the lease is held must fail + self.assertFalse(try_acquire_lease(key)) + + # Once released, it can be acquired again + release_lease(key) + self.assertTrue(try_acquire_lease(key)) + + release_lease(key) + + def test_lease_expires_after_grace_period(self): + """Test that an abandoned lease (e.g. a crashed holder) can be reclaimed.""" + from datetime import timedelta + + from django.utils import timezone + + from common.settings import set_global_setting + from plugin.lease import CLAIM_LEASE, release_lease, try_acquire_lease + + key = '_test_lease_expiry' + + self.assertTrue(try_acquire_lease(key)) + + # A fresh claim cannot be immediately re-acquired by someone else + self.assertFalse(try_acquire_lease(key)) + + # Simulate a crash: back-date the claim beyond the grace period + stale_claim = timezone.now() - CLAIM_LEASE - timedelta(seconds=1) + set_global_setting(f'{key}_CLAIMED_AT', stale_claim.isoformat()) + + # The stale claim is now treated as abandoned, and can be re-acquired + self.assertTrue(try_acquire_lease(key)) + + release_lease(key) + + def test_acquire_lease_blocking_times_out(self): + """Test that acquire_lease_blocking gives up after its timeout, rather than hanging.""" + import time + + from plugin.lease import ( + acquire_lease_blocking, + release_lease, + try_acquire_lease, + ) + + key = '_test_lease_blocking_timeout' + + self.assertTrue(try_acquire_lease(key)) + + start = time.monotonic() + acquired = acquire_lease_blocking(key, timeout=0.3, poll_interval=0.05) + elapsed = time.monotonic() - start + + self.assertFalse(acquired) + self.assertGreaterEqual(elapsed, 0.3) + self.assertLess(elapsed, 5) + + release_lease(key) + + # Once free, a blocking acquire succeeds without waiting for the timeout + self.assertTrue(acquire_lease_blocking(key, timeout=0.3, poll_interval=0.05)) + release_lease(key) + + def test_install_plugin_file_persists_hash_only_after_success(self): + """Test that install_plugin_file() only persists the hash once installed. + + Regression test for a bug found in PR review (inventree/InvenTree#12776): + the hash must not be visible as "up to date" until the install has actually + finished. Otherwise a process killed outright (not a Python exception - an + OOM kill, a container stopped mid-install) between claiming the lease and + finishing would leave the hash pointing at content that was never + installed, and no future check would ever retry it. + """ + from common.settings import get_global_setting + from plugin.registry import registry + + hash_during_install = 'unset' + + def fake_install_plugins_file(): + """Read the persisted hash *while the install is still in progress*. + + This is exactly what a hard kill at this instant would leave behind. + """ + nonlocal hash_during_install + hash_during_install = get_global_setting( + '_PLUGIN_FILE_HASH', '', create=False, cache=False + ) + return True + + with mock.patch( + 'plugin.installer.plugins_file_hash', return_value='test-hash-1' + ): + with mock.patch( + 'plugin.installer.install_plugins_file', + side_effect=fake_install_plugins_file, + ): + registry.install_plugin_file() + + # While the install was in progress, the hash must not yet reflect the + # new (not-yet-installed) value + self.assertEqual(hash_during_install, '') + + # After a successful install, the hash is updated + self.assertEqual( + get_global_setting('_PLUGIN_FILE_HASH', '', create=False), 'test-hash-1' + ) + + def test_install_plugin_file_failure_does_not_persist_hash(self): + """Test that a failed install leaves the hash unset, so it is retried next time.""" + from common.settings import get_global_setting, set_global_setting + from plugin.registry import registry + + set_global_setting('_PLUGIN_FILE_HASH', '') + + with mock.patch( + 'plugin.installer.plugins_file_hash', return_value='test-hash-2' + ): + with mock.patch( + 'plugin.installer.install_plugins_file', return_value=False + ): + registry.install_plugin_file() + + self.assertEqual(get_global_setting('_PLUGIN_FILE_HASH', '', create=False), '') + + def test_install_plugin_file_skips_if_already_current(self): + """Test that install_plugin_file() is a no-op once the hash already matches.""" + from plugin.registry import registry + + with mock.patch( + 'plugin.installer.plugins_file_hash', return_value='test-hash-3' + ): + with mock.patch( + 'plugin.installer.install_plugins_file', return_value=True + ) as mock_install: + registry.install_plugin_file() + mock_install.assert_called_once() + + # A second call with the same (already-installed) hash must not + # install again + registry.install_plugin_file() + mock_install.assert_called_once() + def test_builtin_mandatory_plugins(self): """Test that mandatory builtin plugins are always loaded.""" from plugin.models import PluginConfig @@ -681,6 +876,56 @@ class RegistryTests(TestQueryMixin, PluginRegistryMixin, TestCase): # Test for the 'base' mixin - we expect that this returns "all" plugins base = registry.with_mixin(PluginMixinEnum.BASE, active=None, builtin=None) + + if len(base) != N_CONFIG: + # INSTRUMENTATION (temporary): pinpoint exactly which plugin(s) cause the + # mismatch, and whether it's a missing registry entry, a missing + # PluginConfig, or a loaded plugin that fails the mixin check. + db_keys = set(PluginConfig.objects.values_list('key', flat=True)) + registry_keys = set(registry.plugins.keys()) + matched_keys = {p.slug for p in base} + + print(f'INSTRUMENTATION N_CONFIG={N_CONFIG} len(base)={len(base)}') + print(f'INSTRUMENTATION db_keys ({len(db_keys)}) = {sorted(db_keys)}') + print( + f'INSTRUMENTATION registry_keys ({len(registry_keys)}) = {sorted(registry_keys)}' + ) + print( + f'INSTRUMENTATION matched_keys ({len(matched_keys)}) = {sorted(matched_keys)}' + ) + print( + 'INSTRUMENTATION db_keys - registry_keys (config exists, plugin not loaded) = ' + f'{sorted(db_keys - registry_keys)}' + ) + print( + 'INSTRUMENTATION registry_keys - db_keys (plugin loaded, no config) = ' + f'{sorted(registry_keys - db_keys)}' + ) + + loaded_but_unmatched = (db_keys & registry_keys) - matched_keys + print( + 'INSTRUMENTATION loaded_but_unmatched (config + registry entry exist, ' + f'excluded from base) = {sorted(loaded_but_unmatched)}' + ) + + for slug in loaded_but_unmatched: + plugin = registry.plugins.get(slug) + cfg = registry.get_plugin_config(slug) + try: + mixin_result = f'mixin_enabled(base)={plugin.mixin_enabled("base")}' + except Exception as exc: + mixin_result = f'mixin_enabled(base) raised {exc!r}' + print( + f'INSTRUMENTATION slug={slug!r} plugin_class={type(plugin)!r} ' + f'is_package={getattr(plugin, "is_package", None)!r} ' + f'package_name={getattr(plugin, "package_name", None)!r} ' + f'cfg_active={cfg.active if cfg else None!r} ' + f'cfg_builtin={cfg.is_builtin() if cfg else None!r} ' + f'{mixin_result}' + ) + + print(f'INSTRUMENTATION registry.errors = {dict(registry.errors)!r}') + self.assertEqual(len(base), N_CONFIG, 'Base mixin does not return all plugins') # Next, fetch only "active" plugins diff --git a/src/backend/InvenTree/plugin/test_staticfiles.py b/src/backend/InvenTree/plugin/test_staticfiles.py new file mode 100644 index 0000000000..8ab3b59fe2 --- /dev/null +++ b/src/backend/InvenTree/plugin/test_staticfiles.py @@ -0,0 +1,278 @@ +"""Unit tests for plugin static file collection (see plugin/staticfiles.py). + +These lock down the behaviour introduced while fixing inventree#12769 (concurrent +processes corrupting plugin static output): copy-then-swap semantics, stale file/ +directory cleanup, overwrite behaviour, and engagement of the shared lease. +""" + +import tempfile +from pathlib import Path +from unittest import mock + +from django.contrib.staticfiles.storage import staticfiles_storage +from django.test import TestCase + +import plugin.staticfiles as plugin_staticfiles +from InvenTree.unit_test import PluginRegistryMixin +from plugin.lease import try_acquire_lease +from plugin.registry import registry + + +class FakePlugin: + """Minimal stand-in for a loaded plugin, exposing only what staticfiles.py needs.""" + + def __init__(self, source_dir): + """Store the (local) directory containing this fake plugin's 'static' folder.""" + self.source_dir = source_dir + + def path(self): + """Return the plugin's base directory, matching InvenTreePlugin.path().""" + return Path(self.source_dir) + + +class PluginStaticFilesTestCase(PluginRegistryMixin, TestCase): + """Base class which provides a scratch plugin source directory and destination slug.""" + + def setUp(self): + """Set up a fresh source directory and a unique destination slug for each test.""" + super().setUp() + self.tmp_dir = tempfile.TemporaryDirectory() + self.addCleanup(self.tmp_dir.cleanup) + + self.slug = f'test-static-{self._testMethodName}'.lower().replace('_', '-') + self.destination_prefix = f'plugins/{self.slug}/' + + self.addCleanup(self.clear_destination) + + def clear_destination(self): + """Remove any files this test wrote under its destination prefix.""" + plugin_staticfiles.clear_static_dir(self.destination_prefix) + + def write_source(self, files: dict) -> str: + """Write `files` (relative path -> content) under a 'static' folder in a new source dir. + + Returns the source directory path. + """ + source_dir = tempfile.mkdtemp(dir=self.tmp_dir.name) + static_dir = Path(source_dir) / 'static' + + for relative_path, content in files.items(): + target = static_dir / relative_path + target.parent.mkdir(parents=True, exist_ok=True) + target.write_text(content) + + return source_dir + + def copy_files(self, files: dict): + """Write `files` as a fake plugin's source, then run the real copy for self.slug.""" + source_dir = self.write_source(files) + + with mock.patch.object( + registry, 'get_plugin', return_value=FakePlugin(source_dir) + ): + plugin_staticfiles._copy_plugin_static_files(self.slug) + + def read_destination(self) -> dict: + """Return {relative_path: content} for every file currently at the destination.""" + result = {} + + for relative_path in plugin_staticfiles._iter_storage_files( + self.destination_prefix + ): + with staticfiles_storage.open( + f'{self.destination_prefix}{relative_path}' + ) as f: + result[relative_path] = f.read().decode() + + return result + + +class CopyPluginStaticFilesTests(PluginStaticFilesTestCase): + """Tests for `_copy_plugin_static_files` - the actual file-copying logic.""" + + def test_basic_copy(self): + """Files (including nested ones) are copied to the destination unchanged.""" + self.copy_files({'a.js': 'content-a', 'sub/b.js': 'content-b'}) + + self.assertEqual( + self.read_destination(), {'a.js': 'content-a', 'sub/b.js': 'content-b'} + ) + + def test_no_static_dir_is_a_noop(self): + """A plugin with no 'static' folder at all is silently skipped.""" + source_dir = tempfile.mkdtemp(dir=self.tmp_dir.name) # no 'static' subfolder + + with mock.patch.object( + registry, 'get_plugin', return_value=FakePlugin(source_dir) + ): + plugin_staticfiles._copy_plugin_static_files(self.slug) + + self.assertEqual(self.read_destination(), {}) + + def test_unknown_plugin_is_a_noop(self): + """An unrecognised slug is silently skipped.""" + with mock.patch.object(registry, 'get_plugin', return_value=None): + plugin_staticfiles._copy_plugin_static_files(self.slug) + + self.assertEqual(self.read_destination(), {}) + + def test_overwrite_does_not_leave_suffixed_duplicate(self): + """Re-collecting replaces a file's content in place. + + Storage.save() does not overwrite an existing name by default - it invents + a '..._XXXXXXX' suffixed name instead. This is one of the ways the original + bug corrupted plugin output, so it must not happen here. + """ + self.copy_files({'a.js': 'version-1'}) + self.copy_files({'a.js': 'version-2'}) + + self.assertEqual(self.read_destination(), {'a.js': 'version-2'}) + + def test_stale_file_is_removed(self): + """A file present in the old content but not the new content is removed.""" + self.copy_files({'a.js': 'v1', 'stale.js': 'will-be-removed'}) + self.copy_files({'a.js': 'v1'}) + + self.assertEqual(self.read_destination(), {'a.js': 'v1'}) + + def test_stale_directory_is_removed(self): + """A directory that only contained now-stale files is removed, not left empty.""" + self.copy_files({'sub/stale.js': 'old'}) + self.copy_files({'a.js': 'new'}) + + self.assertEqual(self.read_destination(), {'a.js': 'new'}) + self.assertFalse(staticfiles_storage.exists(f'{self.destination_prefix}sub/')) + self.assertFalse(staticfiles_storage.exists(f'{self.destination_prefix}sub')) + + def test_partial_write_failure_only_affects_the_in_flight_file(self): + """If writing to live storage fails partway, only the in-flight file is affected. + + Files are written in a deterministic (sorted) order. A file processed + before the failure keeps its new content; a file not yet reached keeps + its old content untouched. The file being written at the moment of + failure is a disclosed exception to this: replacing an existing file is + a delete-then-save pair (the storage API has no atomic replace/rename + primitive), so it may be left transiently missing rather than at its + old *or* new content - this is a known, accepted gap (self-healing on + the next successful run), not a regression to guard against here. What + must hold is that nothing *else* is affected, and the exception + propagates rather than being swallowed. + """ + self.copy_files({'a.js': 'v1', 'b.js': 'v1', 'c.js': 'v1'}) + + real_save = staticfiles_storage.save + + def flaky_save(name, content, *args, **kwargs): + if name.endswith('b.js'): + raise RuntimeError('simulated failure writing to live storage') + return real_save(name, content, *args, **kwargs) + + source_dir = self.write_source({'a.js': 'v2', 'b.js': 'v2', 'c.js': 'v2'}) + + with mock.patch.object( + registry, 'get_plugin', return_value=FakePlugin(source_dir) + ): + with mock.patch.object(staticfiles_storage, 'save', side_effect=flaky_save): + with self.assertRaises(RuntimeError): + plugin_staticfiles._copy_plugin_static_files(self.slug) + + destination = self.read_destination() + self.assertEqual(destination['a.js'], 'v2') # sorts before 'b.js' - written + self.assertEqual(destination['c.js'], 'v1') # sorts after 'b.js' - untouched + self.assertNotIn('b.js', destination) # disclosed gap - see docstring above + + def test_source_read_failure_does_not_touch_destination(self): + """If reading the plugin's own source files fails, live content is untouched.""" + self.copy_files({'a.js': 'v1'}) + + source_dir = self.write_source({'a.js': 'v2', 'bad.js': 'v2'}) + + real_read_bytes = Path.read_bytes + + def flaky_read_bytes(self): + if self.name == 'bad.js': + raise OSError('simulated read failure') + return real_read_bytes(self) + + with mock.patch.object( + registry, 'get_plugin', return_value=FakePlugin(source_dir) + ): + with mock.patch.object(Path, 'read_bytes', flaky_read_bytes): + with self.assertRaises(OSError): + plugin_staticfiles._copy_plugin_static_files(self.slug) + + # Nothing was written - the original content is exactly as it was + self.assertEqual(self.read_destination(), {'a.js': 'v1'}) + + +class StaticFilesLeaseEngagementTests(PluginStaticFilesTestCase): + """Tests that the public staticfiles.py entry points actually engage the shared lease.""" + + def with_short_timeout(self): + """Patch acquire_lease_blocking (as imported into staticfiles.py) to fail fast.""" + return mock.patch.object( + plugin_staticfiles, + 'acquire_lease_blocking', + side_effect=lambda key, **kw: try_acquire_lease(key), + ) + + def test_copy_plugin_static_files_skips_when_lease_held(self): + """copy_plugin_static_files() must not run while the lease is held elsewhere.""" + source_dir = self.write_source({'a.js': 'v1'}) + + self.assertTrue(try_acquire_lease(plugin_staticfiles.PLUGIN_STATIC_FILES_LEASE)) + try: + with self.with_short_timeout(): + with mock.patch.object( + registry, 'get_plugin', return_value=FakePlugin(source_dir) + ): + plugin_staticfiles.copy_plugin_static_files( + self.slug, check_reload=False + ) + finally: + plugin_staticfiles.release_lease( + plugin_staticfiles.PLUGIN_STATIC_FILES_LEASE + ) + + # The lease was held, so nothing should have been copied + self.assertEqual(self.read_destination(), {}) + + def test_collect_plugins_static_files_skips_when_lease_held(self): + """collect_plugins_static_files() must not run while the lease is held elsewhere.""" + self.assertTrue(try_acquire_lease(plugin_staticfiles.PLUGIN_STATIC_FILES_LEASE)) + try: + with self.with_short_timeout(): + with mock.patch.object(registry, 'check_reload'): + # Should return immediately without raising or iterating plugins + plugin_staticfiles.collect_plugins_static_files() + finally: + plugin_staticfiles.release_lease( + plugin_staticfiles.PLUGIN_STATIC_FILES_LEASE + ) + + def test_clear_plugin_static_files_skips_when_lease_held(self): + """clear_plugin_static_files() must not run while the lease is held elsewhere.""" + self.copy_files({'a.js': 'v1'}) + + self.assertTrue(try_acquire_lease(plugin_staticfiles.PLUGIN_STATIC_FILES_LEASE)) + try: + with self.with_short_timeout(): + plugin_staticfiles.clear_plugin_static_files(self.slug) + finally: + plugin_staticfiles.release_lease( + plugin_staticfiles.PLUGIN_STATIC_FILES_LEASE + ) + + # The lease was held, so the file should still be there + self.assertEqual(self.read_destination(), {'a.js': 'v1'}) + + def test_copy_plugin_static_files_runs_once_lease_is_free(self): + """Sanity check: with no competing lease, the copy proceeds normally.""" + source_dir = self.write_source({'a.js': 'v1'}) + + with mock.patch.object( + registry, 'get_plugin', return_value=FakePlugin(source_dir) + ): + plugin_staticfiles.copy_plugin_static_files(self.slug, check_reload=False) + + self.assertEqual(self.read_destination(), {'a.js': 'v1'})