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 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 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 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)