From 182f95cc48029617825dabede3fc812c36995146 Mon Sep 17 00:00:00 2001 From: "Chris St. Pierre" Date: Tue, 19 Mar 2013 15:04:29 -0400 Subject: Core: added more debug logging for core methods --- src/lib/Bcfg2/Server/Core.py | 22 +++++++++++++++++++++- 1 file changed, 21 insertions(+), 1 deletion(-) (limited to 'src/lib/Bcfg2/Server/Core.py') diff --git a/src/lib/Bcfg2/Server/Core.py b/src/lib/Bcfg2/Server/Core.py index 782aafbf1..72c0953b8 100644 --- a/src/lib/Bcfg2/Server/Core.py +++ b/src/lib/Bcfg2/Server/Core.py @@ -396,6 +396,7 @@ class BaseCore(object): def shutdown(self): """ Perform plugin and FAM shutdown tasks. """ + self.logger.debug("Shutting down core...") if not self.terminate.isSet(): self.terminate.set() self.fam.shutdown() @@ -429,6 +430,8 @@ class BaseCore(object): hook. :type metadata: Bcfg2.Server.Plugins.Metadata.ClientMetadata """ + self.logger.debug("Running %s hooks for %s" % (hook, + metadata.hostname)) start = time.time() try: for plugin in \ @@ -462,6 +465,7 @@ class BaseCore(object): client :type data: list of lxml.etree._Element objects """ + self.logger.debug("Validating structures for %s" % metadata.hostname) for plugin in \ self.plugins_by_type(Bcfg2.Server.Plugin.StructureValidator): try: @@ -488,6 +492,7 @@ class BaseCore(object): client :type data: list of lxml.etree._Element objects """ + self.logger.debug("Validating goals for %s" % metadata.hostname) for plugin in self.plugins_by_type(Bcfg2.Server.Plugin.GoalValidator): try: plugin.validate_goals(metadata, data) @@ -508,6 +513,7 @@ class BaseCore(object): :type metadata: Bcfg2.Server.Plugins.Metadata.ClientMetadata :returns: list of :class:`lxml.etree._Element` objects """ + self.logger.debug("Getting structures for %s" % metadata.hostname) structures = list(chain(*[struct.BuildStructures(metadata) for struct in self.structures])) sbundles = [b.get('name') for b in structures if b.tag == 'Bundle'] @@ -530,6 +536,7 @@ class BaseCore(object): structures to. Modified in-place. :type config: lxml.etree._Element """ + self.logger.debug("Binding structures for %s" % metadata.hostname) for astruct in structures: try: self.BindStructure(astruct, metadata) @@ -546,6 +553,9 @@ class BaseCore(object): :param metadata: Client metadata to bind structure for :type metadata: Bcfg2.Server.Plugins.Metadata.ClientMetadata """ + self.logger.debug("Binding structure %s for %s" % + (structure.get("name", "unknown"), + metadata.hostname)) for entry in structure.getchildren(): if entry.tag.startswith("Bound"): entry.tag = entry.tag[5:] @@ -621,6 +631,7 @@ class BaseCore(object): :type client: string :returns: :class:`lxml.etree._Element` - A complete Bcfg2 configuration document """ + self.logger.debug("Building configuration for %s" % client) start = time.time() config = lxml.etree.Element("Configuration", version='2.0', revision=self.revision) @@ -748,6 +759,7 @@ class BaseCore(object): :type mode: string :returns: list of Decision tuples ``(, )`` """ + self.logger.debug("Getting decision list for %s" % metadata.hostname) result = [] for plugin in self.plugins_by_type(Bcfg2.Server.Plugin.Decision): try: @@ -776,6 +788,7 @@ class BaseCore(object): else: imd = self.metadata_cache.get(client_name, None) if not imd: + self.logger.debug("Building metadata for %s" % client_name) imd = self.metadata.get_initial_metadata(client_name) for conn in self.connectors: grps = conn.get_additional_groups(imd) @@ -797,6 +810,7 @@ class BaseCore(object): :param statistics: The statistics document to process :type statistics: lxml.etree._Element """ + self.logger.debug("Processing statistics for %s" % client_name) meta = self.build_metadata(client_name) state = statistics.find(".//Statistics") if state.get('version') >= '2.0': @@ -922,6 +936,7 @@ class BaseCore(object): return func.__doc__ @exposed + @track_statistics() def DeclareVersion(self, address, version): """ Declare the client version. @@ -932,7 +947,9 @@ class BaseCore(object): :returns: bool - True on success :raises: :exc:`xmlrpclib.Fault` """ - client = self.resolve_client(address)[0] + client = self.resolve_client(address, metadata=False)[0] + self.logger.debug("%s is running Bcfg2 client version %s" % (client, + version)) try: self.metadata.set_version(client, version) except (Bcfg2.Server.Plugin.MetadataConsistencyError, @@ -954,6 +971,7 @@ class BaseCore(object): """ resp = lxml.etree.Element('probes') client, metadata = self.resolve_client(address, cleanup_cache=True) + self.logger.debug("Getting probes for %s" % client) try: for plugin in self.plugins_by_type(Bcfg2.Server.Plugin.Probing): for probe in plugin.GetProbes(metadata): @@ -975,6 +993,7 @@ class BaseCore(object): :raises: :exc:`xmlrpclib.Fault` """ client, metadata = self.resolve_client(address) + self.logger.debug("Receiving probe data from %s" % client) if self.metadata_cache_mode == 'cautious': # clear the metadata cache right after building the # metadata object; that way the cache is cleared for any @@ -1021,6 +1040,7 @@ class BaseCore(object): :raises: :exc:`xmlrpclib.Fault` """ client = self.resolve_client(address, metadata=False)[0] + self.logger.debug("%s sets its profile to %s" % (client, profile)) try: self.metadata.set_profile(client, profile, address) except (Bcfg2.Server.Plugin.MetadataConsistencyError, -- cgit v1.2.3-1-g7c22 From 71d7285c405bd639f1f9f2642ea8fb567b97caec Mon Sep 17 00:00:00 2001 From: "Chris St. Pierre" Date: Tue, 19 Mar 2013 15:05:51 -0400 Subject: Debug improvements: * Added (set|toggle)_core_debug RMI methods to set debugging in the core * Enable plugin debugging when run with -d * Allow enabling debugging on Reporting plugin before threads have started --- src/lib/Bcfg2/Server/Core.py | 71 +++++++++++++++++++++++++++++++++++++++----- 1 file changed, 64 insertions(+), 7 deletions(-) (limited to 'src/lib/Bcfg2/Server/Core.py') diff --git a/src/lib/Bcfg2/Server/Core.py b/src/lib/Bcfg2/Server/Core.py index 72c0953b8..9be71e2e2 100644 --- a/src/lib/Bcfg2/Server/Core.py +++ b/src/lib/Bcfg2/Server/Core.py @@ -99,9 +99,7 @@ class BaseCore(object): #: The Bcfg2 repository directory self.datastore = setup['repo'] - if setup['debug']: - level = logging.DEBUG - elif setup['verbose']: + if setup['verbose']: level = logging.INFO else: level = logging.WARNING @@ -119,6 +117,25 @@ class BaseCore(object): #: A :class:`logging.Logger` object for use by the core self.logger = logging.getLogger('bcfg2-server') + #: Log levels for the various logging handlers with debug True + #: and False. Each loglevel dict is a dict of ``logger name + #: => log level``; the logger names are set in + #: :mod:`Bcfg2.Logger`. The logger name ``default`` is + #: special, and will be used for any log handlers whose name + #: does not appear elsewhere in the dict. At a minimum, + #: ``default`` must be provided. + self._loglevels = {True: dict(default=logging.DEBUG), + False: dict(console=logging.INFO, + default=level)} + + #: Used to keep track of the current debug state of the core. + self.debug_flag = False + + # enable debugging on the core now. debugging is enabled on + # everything else later + if setup['debug']: + self.set_core_debug(None, setup['debug']) + try: filemonitor = \ Bcfg2.Server.FileMonitor.available[setup['filemonitor']] @@ -299,6 +316,11 @@ class BaseCore(object): #: metadata self.metadata_cache = Cache() + if self.debug_flag: + # enable debugging on everything else. + self.plugins[plugin].set_debug(self.debug_flag) + + def plugins_by_type(self, base_cls): """ Return a list of loaded plugins that match the passed type. @@ -731,6 +753,7 @@ class BaseCore(object): self.shutdown() raise + self.set_debug(None, self.debug_flag) self._block() def _daemonize(self): @@ -1141,9 +1164,17 @@ class BaseCore(object): :type address: tuple :returns: bool - The new debug state of the FAM """ - for plugin in self.plugins.values(): - plugin.toggle_debug() - return self.toggle_fam_debug(address) + return self.set_debug(address, not self.debug_flag) + + @exposed + def toggle_core_debug(self, address): + """ Toggle debug status of the server core + + :param address: Client (address, hostname) pair + :type address: tuple + :returns: bool - The new debug state of the FAM + """ + return self.set_core_debug(address, not self.debug_flag) @exposed def toggle_fam_debug(self, _): @@ -1157,6 +1188,8 @@ class BaseCore(object): def set_debug(self, address, debug): """ Explicitly set debug status of the FAM and all plugins + :param address: Client (address, hostname) pair + :type address: tuple :param debug: The new debug status. This can either be a boolean, or a string describing the state (e.g., "true" or "false"; case-insensitive) @@ -1167,7 +1200,31 @@ class BaseCore(object): debug = debug.lower() == "true" for plugin in self.plugins.values(): plugin.set_debug(debug) - return self.set_fam_debug(address, debug) + rv = self.set_core_debug(address, debug) + return self.set_fam_debug(address, debug) and rv + + @exposed + def set_core_debug(self, _, debug): + """ Explicity set debug status of the server core + + :param debug: The new debug status. This can either be a + boolean, or a string describing the state (e.g., + "true" or "false"; case-insensitive) + :type debug: bool or string + :returns: bool - The new debug state of the FAM + """ + if debug not in [True, False]: + debug = debug.lower() == "true" + self.debug_flag = debug + self.logger.info("Core: debug = %s" % debug) + levels = self._loglevels[self.debug_flag] + for handler in logging.root.handlers: + level = levels.get(handler.get_name(), levels['default']) + self.logger.debug("Setting %s log handler to %s" % + (handler.get_name(), + logging.getLevelName(level))) + handler.setLevel(level) + return self.debug_flag @exposed def set_fam_debug(self, _, debug): -- cgit v1.2.3-1-g7c22