def test_panoptes_plugin_manager(self): matching_test_plugins_found = 0 context = TestPanoptesPluginManagerContext() plugin_manager = PanoptesPluginManager( plugin_type='polling', plugin_class=PanoptesPollingPlugin, panoptes_context=context) plugins = plugin_manager.getPluginsOfCategory('polling') self.assertGreater(len(plugins), 0) for plugin in plugins: if 'Test Polling Plugin' in plugin.name: matching_test_plugins_found += 1 self.assertEqual(matching_test_plugins_found, 3) polling_plugin = plugin_manager.getPluginByName( name='Test Polling Plugin', category='polling') self.assertEqual(polling_plugin.name, 'Test Polling Plugin') self.assertEqual( os.path.split(polling_plugin.config_filename)[1], 'plugin_polling_test.panoptes-plugin') polling_plugin_second_instance = plugin_manager.getPluginByName( name='Test Polling Plugin Second Instance', category='polling') self.assertEqual(polling_plugin_second_instance.name, 'Test Polling Plugin Second Instance') self.assertEqual( os.path.split(polling_plugin_second_instance.config_filename)[1], 'plugin_polling_test_second_instance.panoptes-plugin')
def test_panoptes_plugin_manager(self): matching_test_plugins_found = 0 context = TestPanoptesPluginManagerContext() plugin_manager = PanoptesPluginManager( plugin_type=u'polling', plugin_class=PanoptesPollingPlugin, panoptes_context=context) plugins = plugin_manager.getPluginsOfCategory(u'polling') self.assertGreater(len(plugins), 0) for plugin in plugins: if u'Test Polling Plugin' in plugin.name: matching_test_plugins_found += 1 self.assertEqual(matching_test_plugins_found, 3) polling_plugin = plugin_manager.getPluginByName( name=u'Test Polling Plugin', category=u'polling') self.assertEqual(polling_plugin.name, u'Test Polling Plugin') self.assertEqual( os.path.split(polling_plugin.config_filename)[1], u'plugin_polling_test.panoptes-plugin') polling_plugin_second_instance = plugin_manager.getPluginByName( name=u'Test Polling Plugin Second Instance', category=u'polling') self.assertEqual(polling_plugin_second_instance.name, u'Test Polling Plugin Second Instance') self.assertEqual( os.path.split(polling_plugin_second_instance.config_filename)[1], u'plugin_polling_test_second_instance.panoptes-plugin') # Test unloading of th plugin modules, including error handling yapsy_modules = [ m for m in sys.modules.keys() if m.startswith(u'yapsy_loaded_plugin') ] self.assertEqual(len(yapsy_modules), 3) with LogCapture(attributes=self.extract) as log_capture: del sys.modules['yapsy_loaded_plugin_Test_Polling_Plugin_0'] plugin_manager.unload_modules() log_capture.check_present(( 'panoptes.tests.test_plugin_manager', 'DEBUG', 'Deleting module: yapsy_loaded_plugin_Test_Polling_Plugin_0' ), ( 'panoptes.tests.test_plugin_manager', 'ERROR', 'Error trying to delete module "yapsy_loaded_plugin_Test_Polling_Plugin_0"' ), ( 'panoptes.tests.test_plugin_manager', 'DEBUG', 'Deleting module: yapsy_loaded_plugin_Test_Polling_Plugin_2_0' ), ('panoptes.tests.test_plugin_manager', 'DEBUG', 'Deleting module: yapsy_loaded_plugin_Test_Polling_Plugin_Second_Instance_0' ), order_matters=False) yapsy_modules = [ m for m in sys.modules.keys() if m.startswith(u'yapsy_loaded_plugin') ] self.assertEqual(len(yapsy_modules), 0)
def polling_plugin_scheduler_task(celery_beat_service): """ This function is the workhorse of the Polling Plugin Scheduler module. It detects changes in plugins and their configuration and updates the Celery Beat schedule accordingly. Args: celery_beat_service (celery.beat.Service): The Celery Beat Service instance associated with this Plugin\ Scheduler Returns: None """ start_time = time.time() try: resource_cache = PanoptesResourceCache(panoptes_context) resource_cache.setup_resource_cache() except: logger.exception(u'Could not create resource cache, skipping cycle') return try: plugin_manager = PanoptesPluginManager( plugin_type=u'polling', plugin_class=PanoptesPollingPlugin, plugin_info_class=PanoptesPollingPluginInfo, panoptes_context=panoptes_context, kv_store_class=PanoptesPollingPluginAgentKeyValueStore) plugins = plugin_manager.getPluginsOfCategory(category_name=u'polling') logger.info(u'Found %d plugins' % len(plugins)) except: logger.exception( u'Error trying to load Polling plugins, skipping cycle') return new_schedule = dict() for plugin in plugins: logger.info(u'Found plugin "%s", version %s at %s ' % (plugin.name, plugin.version, plugin.path)) try: logger.info(u'Plugin "%s" has configuration: %s' % (plugin.name, plugin.config)) logger.info( u'Plugin %s has plugin module time %s (UTC) and config mtime %s (UTC)' % (plugin.name, plugin.moduleMtime, plugin.configMtime)) if plugin.execute_frequency <= 0: logger.info( u'Plugin %s has an invalid execution frequency (%d), skipping plugin' % (plugin.name, plugin.execute_frequency)) continue if not plugin.resource_filter: logger.info( u'Plugin "%s" does not have any resource filter specified, skipping plugin' % plugin.name) continue except PanoptesPluginConfigurationError as e: logger.error( u'Error reading/parsing configuration for plugin "%s", skipping plugin. Error: %s' % (plugin.name, repr(e))) try: resource_set = resource_cache.get_resources(plugin.resource_filter) except Exception as e: logger.info( u'Error in applying resource filter "%s" for plugin "%s", skipping plugin: %s' % (plugin.resource_filter, plugin.name, repr(e))) continue if len(resource_set) == 0: logger.info( u'No resources found for plugin "%s" after applying resource filter "%s", skipping plugin' % (plugin.name, plugin.resource_filter)) logger.info(u'Length of resource set {} for plugin {}'.format( len(resource_set), plugin.name)) for resource in resource_set: logger.debug( u'Going to add task for plugin "%s" with execute frequency %d, args "%s", resources %s' % (plugin.name, plugin.execute_frequency, plugin.config, resource)) plugin.data = resource task_name = u':'.join([ plugin.normalized_name, plugin.signature, str(resource.resource_id) ]) new_schedule[task_name] = { u'task': const.POLLING_PLUGIN_AGENT_MODULE_NAME, u'schedule': timedelta(seconds=plugin.execute_frequency), u'args': (plugin.name, resource.serialization_key), u'last_run_at': datetime.utcfromtimestamp(plugin.last_executed), u'options': { u'expires': expires(plugin), u'time_limit': time_limit(plugin) } } resource_cache.close_resource_cache() logger.info( 'Going to unload plugin modules. Length of sys.modules before unloading modules: %d' % len(sys.modules)) plugin_manager.unload_modules() logger.info( 'Unloaded plugin modules. Length of sys.modules after unloading modules: %d' % len(sys.modules)) try: scheduler = celery_beat_service.scheduler scheduler.update(logger, new_schedule) end_time = time.time() logger.info(u'Scheduled %d tasks in %.2fs' % (len(new_schedule), end_time - start_time)) logger.info(u'RSS memory: %dKB' % getrusage(RUSAGE_SELF).ru_maxrss) except: logger.exception(u'Error in updating schedule for Polling Plugins') logger.info('RSS memory: %dKB' % getrusage(RUSAGE_SELF).ru_maxrss)
def execute_plugin(self): """ This method loads, executes and returns the results of the plugin The steps involved are: * Create a PanoptesPluginManager for the type of plugins we are interested in and then try and load the \ named plugin * Check if the plugin should be executed right now based on the last execution and results time and the \ configured execution and results caching time * setup a PluginContext and attempt to take a lock on the plugin name and it's signature \ (which is hash of the plugin's config and data) * Try and run the plugin * If the plugin execution returns without errors, then update the last execution time * Pass the results obtained to the callback function * If the callback function succeeds, then update the last successful run time Returns: None """ logger = self._logger config = self._panoptes_context.config_dict utc_epoch = int(time.time()) logger.info(u'Attempting to execute plugin "%s"' % self._plugin_name) try: plugin_manager = PanoptesPluginManager( plugin_type=self._plugin_type, plugin_class=self._plugin_class, plugin_info_class=self._plugin_info_class, plugin_data=self._plugin_data, panoptes_context=self._panoptes_context, kv_store_class=self._plugin_agent_kv_store_class) plugin = plugin_manager.getPluginByName(name=self._plugin_name, category=self._plugin_type) except Exception as e: logger.error(u'Error trying to load plugin "%s": %s' % (self._plugin_name, repr(e))) return if not plugin: logger.warn(u'No plugin named "%s" found in "%s"' % (self._plugin_name, config[self._plugin_type][u'plugins_paths'])) return if not plugin.execute_now: return try: plugin_context = self._get_context(plugin) except: self.exception(plugin, u'Could not setup context for plugin') return self.info( plugin, u'Attempting to get lock for plugin "%s"' % self._plugin_name) try: lock = plugin.lock except: self.exception(plugin, u'Error in acquiring lock') return if lock is None or not lock.locked: return self.info(plugin, u'Acquired lock') self.info( plugin, u'Going to run plugin "{}", version "{}", which last executed at {} (UTC) ({} seconds ago) and ' u'last produced results at {} (UTC) ({} seconds ago), module mtime {} (UTC), config mtime {} (' u'UTC)'.format(plugin.name, plugin.version, plugin.last_executed, plugin.last_executed_age, plugin.last_results, plugin.last_results_age, plugin.moduleMtime, plugin.configMtime)) results = None plugin_start_time = time.time() try: results = plugin.plugin_object.run(plugin_context) except: self.exception(plugin, u'Failed to execute plugin') finally: plugin_end_time = time.time() plugin.last_executed = utc_epoch if results is None: self.warn(plugin, u'Plugin did not return any results') elif not isinstance(results, self._plugin_result_class): self.warn( plugin, u'Plugin returned an unexpected result type: "{}"'.format( type(results).__name__)) else: self.info( plugin, u'Plugin returned a result set with {} members'.format( len(results))) if len(results) > 0: # Non-empty result set - send the results to the callback function callback_start_time = time.time() try: self._results_callback(self._panoptes_context, results, plugin) except Exception as e: self.exception( plugin, u'Results callback function failed: {}'.format(e)) return finally: callback_end_time = time.time() self.info( plugin, u'Callback function ran in {:0.2f} seconds'.format( callback_end_time - callback_start_time)) # If the callback was successful, then set the last results time # The logic behind this is: in case the callback fails, then the # plugin should be re-executed again after the plugin # execute_frequency seconds - the execution should not be # preempted by the results caching logic, which # depends on the last results time in the KV store plugin.last_results = utc_epoch self.info( plugin, u'Ran in {:0.2f} seconds'.format(plugin_end_time - plugin_start_time)) try: lock.release() except: self.exception(plugin, u'Failed to release lock for plugin') else: self.info(plugin, u'Released lock') plugin_manager.unload_modules() gc_start_time = time.time() gc.collect() gc_end_time = time.time() self.info( plugin, u'GC took %.2f seconds. There are %d garbage objects.' % (gc_end_time - gc_start_time, len(gc.garbage)))
def polling_plugin_get_schedule(): start_time = time.time() try: resource_cache = PanoptesResourceCache(panoptes_context) resource_cache.setup_resource_cache() except Exception as e: logger.exception(u'Could not create resource cache. {}'.format( repr(e))) return {} try: plugin_manager = PanoptesPluginManager( plugin_type=u'polling', plugin_class=PanoptesPollingPlugin, plugin_info_class=PanoptesPollingPluginInfo, panoptes_context=panoptes_context, kv_store_class=PanoptesPollingPluginAgentKeyValueStore) plugins = plugin_manager.getPluginsOfCategory(category_name=u'polling') logger.info(u'Found %d plugins' % len(plugins)) except Exception as e: logger.exception( u'Error trying to load Polling plugins, skipping cycle. {}'.format( repr(e))) return {} new_schedule = dict() for plugin in plugins: logger.info(u'Found plugin "%s", version %s at %s ' % (plugin.name, plugin.version, plugin.path)) try: logger.info(u'Plugin "%s" has configuration: %s' % (plugin.name, plugin.config)) logger.info( u'Plugin %s has plugin module time %s (UTC) and config mtime %s (UTC)' % (plugin.name, plugin.moduleMtime, plugin.configMtime)) if plugin.execute_frequency <= 0: logger.info( u'Plugin %s has an invalid execution frequency (%d), skipping plugin' % (plugin.name, plugin.execute_frequency)) continue if not plugin.resource_filter: logger.info( u'Plugin "%s" does not have any resource filter specified, skipping plugin' % plugin.name) continue except PanoptesPluginConfigurationError as e: logger.error( u'Error reading/parsing configuration for plugin "%s", skipping plugin. Error: %s' % (plugin.name, repr(e))) try: resource_set = resource_cache.get_resources(plugin.resource_filter) except Exception as e: logger.info( u'Error in applying resource filter "%s" for plugin "%s", skipping plugin: %s' % (plugin.resource_filter, plugin.name, repr(e))) continue if len(resource_set) == 0: logger.info( u'No resources found for plugin "%s" after applying resource filter "%s", skipping plugin' % (plugin.name, plugin.resource_filter)) logger.info(u'Length of resource set {} for plugin {}'.format( len(resource_set), plugin.name)) for resource in resource_set: logger.debug( u'Going to add task for plugin "%s" with execute frequency %d, args "%s", resources %s' % (plugin.name, plugin.execute_frequency, plugin.config, resource)) plugin.data = resource task_name = u':'.join([ plugin.normalized_name, plugin.signature, str(resource.resource_id) ]) new_schedule[task_name] = { u'task': const.POLLING_PLUGIN_AGENT_MODULE_NAME, u'schedule': timedelta(seconds=plugin.execute_frequency), u'args': (plugin.name, resource.serialization_key), u'last_run_at': datetime.utcfromtimestamp(plugin.last_executed), u'options': { u'expires': expires(plugin), u'time_limit': time_limit(plugin) } } resource_cache.close_resource_cache() logger.info( 'Going to unload plugin modules. Length of sys.modules before unloading modules: %d' % len(sys.modules)) plugin_manager.unload_modules() logger.info( 'Unloaded plugin modules. Length of sys.modules after unloading modules: %d' % len(sys.modules)) logger.info('Created Schedule With {} entries in {} seconds'.format( len(new_schedule.keys()), time.time() - start_time)) return new_schedule
def discovery_plugin_scheduler_task(celery_beat_service): """ This function is the workhorse of the Discovery Plugin Scheduler module. It detects changes in plugins and their configuration and updates the Celery Beat schedule accordingly. Args: celery_beat_service (celery.beat.Service): The Celery Beat Service object associated with this Plugin Scheduler Returns: None """ start_time = time.time() try: plugin_manager = PanoptesPluginManager( plugin_type=u'discovery', plugin_class=PanoptesDiscoveryPlugin, plugin_info_class=PanoptesPluginInfo, panoptes_context=panoptes_context, kv_store_class=PanoptesDiscoveryPluginAgentKeyValueStore) plugins = plugin_manager.getPluginsOfCategory( category_name=u'discovery') except: logger.exception( u'Error trying to load Discovery plugins, skipping cycle') return new_schedule = dict() for plugin in plugins: logger.info(u'Found plugin "%s", version %s at %s ' % (plugin.name, plugin.version, plugin.path)) try: logger.info(u'Plugin "%s" has configuration: %s' % (plugin.name, plugin.config)) logger.info( u'Plugin %s has plugin module time %s (UTC) and config mtime %s (UTC)' % (plugin.name, plugin.moduleMtime, plugin.configMtime)) if plugin.execute_frequency <= 0: logger.info( u'Plugin %s has an invalid execution frequency (%d), skipping plugin' % (plugin.name, plugin.execute_frequency)) continue except PanoptesPluginConfigurationError as e: logger.error( u'Error reading/parsing configuration for plugin %s, skipping plugin. Error: %s' % (plugin.name, repr(e))) logger.debug( u'Going to add task for plugin "%s" with execute frequency %d and args "%s"' % (plugin.name, plugin.execute_frequency, plugin.config)) task_name = u':'.join([plugin.normalized_name, plugin.signature]) new_schedule[task_name] = { u'task': const.DISCOVERY_PLUGIN_AGENT_MODULE_NAME, u'schedule': timedelta(seconds=plugin.execute_frequency), u'last_run_at': datetime.utcfromtimestamp(plugin.last_executed), u'args': (plugin.name, ), u'options': { u'expires': expires(plugin), u'time_limit': time_limit(plugin) } } logger.info( u'Going to unload plugin modules. Length of sys.modules before unloading modules: %d' % len(sys.modules)) plugin_manager.unload_modules() logger.info( u'Unloaded plugin modules. Length of sys.modules after unloading modules: %d' % len(sys.modules)) try: scheduler = celery_beat_service.scheduler scheduler.update(logger, new_schedule) end_time = time.time() logger.info(u'Scheduled %d tasks in %.2fs' % (len(new_schedule), end_time - start_time)) except: logger.exception(u'Error in updating schedule for Discovery Plugins') logger.info(u'RSS memory: %dKB' % getrusage(RUSAGE_SELF).ru_maxrss)