Merge pull request ceph#30961 from rjfd/wip-mgr-module-logging

mgr: module logging infrastructure

Reviewed-by: Ernesto Puertat <epuertat@redhat.com>
Reviewed-by: Ricardo Marques <rimarques@suse.com>
Reviewed-by: Laura Paduano <lpaduano@suse.com>

doc/mgr/modules.rst

@@ -48,13 +48,58 @@ or older versions of Ceph.
 Logging
 -------
 
-``MgrModule`` instances have a ``log`` property which is a logger instance that
-sends log messages into the Ceph logging layer where they will be recorded
-in the mgr daemon's log file.
+Logging in Ceph manager modules is done as in any other Python program. Just
+import the ``logging`` package and get a logger instance with the
+``logging.getLogger`` function.
+
+Each module has a ``log_level`` option that specifies the current Python
+logging level of the module.
+To change or query the logging level of the module use the following Ceph
+commands::
+
+  ceph config get mgr mgr/<module_name>/log_level
+  ceph config set mgr mgr/<module_name>/log_level <info|debug|critical|error|warning|>
+
+The logging level used upon the module's start is determined by the current
+logging level of the mgr daemon, unless if the ``log_level`` option was
+previously set with the ``config set ...`` command. The mgr daemon logging
+level is mapped to the module python logging level as follows:
+
+* <= 0 is CRITICAL
+* <= 1 is WARNING
+* <= 4 is INFO
+* <= +inf is DEBUG
+
+We can unset the module log level and fallback to the mgr daemon logging level
+by running the following command::
+
+  ceph config set mgr mgr/<module_name>/log_level ''
+
+By default, modules' logging messages are processed by the Ceph logging layer
+where they will be recorded in the mgr daemon's log file.
+But it's also possible to send a module's logging message to it's own file.
+
+The module's log file will be located in the same directory as the mgr daemon's
+log file with the following name pattern::
+
+   <mgr_daemon_log_file_name>.<module_name>.log
+
+To enable the file logging on a module use the following command::
+
+   ceph config set mgr mgr/<module_name>/log_to_file true
+
+When the module's file logging is enabled, module's logging messages stop
+being written to the mgr daemon's log file and are only written to the
+module's log file.
+
+It's also possible to check the status and disable the file logging with the
+following commands::
+
+   ceph config get mgr mgr/<module_name>/log_to_file
+   ceph config set mgr mgr/<module_name>/log_to_file false
+
+
 
-Use it the same way you would any other python logger.  The python
-log levels debug, info, warn, err are mapped into the Ceph
-severities 20, 4, 1 and 0 respectively.
 
 Exposing commands
 -----------------
@@ -348,20 +393,6 @@ implementation may change to serialize arguments and return
 values.
 
 
-Logging
--------
-
-Use your module's ``log`` attribute as your logger.  This is a logger
-configured to output via the ceph logging framework, to the local ceph-mgr
-log files.
-
-Python log severities are mapped to ceph severities as follows:
-
-* DEBUG is 20
-* INFO is 4
-* WARN is 1
-* ERR is 0
-
 Shutting down cleanly
 ---------------------
 

src/mgr/ActivePyModule.cc

@@ -175,10 +175,10 @@ void ActivePyModule::config_notify()
   }
 
   Gil gil(py_module->pMyThreadState, true);
-  dout(20) << "Calling " << py_module->get_name() << ".config_notify..."
+  dout(20) << "Calling " << py_module->get_name() << "._config_notify..."
 	   << dendl;
   auto remoteResult = PyObject_CallMethod(pClassInstance,
-					  const_cast<char*>("config_notify"),
+					  const_cast<char*>("_config_notify"),
 					  (char*)NULL);
   if (remoteResult != nullptr) {
     Py_DECREF(remoteResult);

src/mgr/BaseMgrModule.cc

@@ -528,15 +528,14 @@ get_daemon_status(BaseMgrModule *self, PyObject *args)
 static PyObject*
 ceph_log(BaseMgrModule *self, PyObject *args)
 {
-  int level = 0;
   char *record = nullptr;
-  if (!PyArg_ParseTuple(args, "is:log", &level, &record)) {
+  if (!PyArg_ParseTuple(args, "s:log", &record)) {
     return nullptr;
   }
 
   ceph_assert(self->this_module);
 
-  self->this_module->log(level, record);
+  self->this_module->log(record);
 
   Py_RETURN_NONE;
 }

src/mgr/BaseMgrStandbyModule.cc

@@ -152,15 +152,14 @@ ceph_get_active_uri(BaseMgrStandbyModule *self, PyObject *args)
 static PyObject*
 ceph_log(BaseMgrStandbyModule *self, PyObject *args)
 {
-  int level = 0;
   char *record = nullptr;
-  if (!PyArg_ParseTuple(args, "is:log", &level, &record)) {
+  if (!PyArg_ParseTuple(args, "s:log", &record)) {
     return nullptr;
   }
 
   ceph_assert(self->this_module);
 
-  self->this_module->log(level, record);
+  self->this_module->log(record);
 
   Py_RETURN_NONE;
 }

src/mgr/PyModule.cc

@@ -476,7 +476,8 @@ int PyModule::walk_dict_list(
 int PyModule::load_commands()
 {
   PyObject *pRegCmd = PyObject_CallMethod(pClass,
-  const_cast<char*>("_register_commands"), const_cast<char*>("()"));
+      const_cast<char*>("_register_commands"), const_cast<char*>("(s)"),
+      module_name.c_str());
   if (pRegCmd != nullptr) {
     Py_DECREF(pRegCmd);
   } else {

src/mgr/PyModuleRunner.cc

@@ -92,11 +92,11 @@ void PyModuleRunner::shutdown()
   dead = true;
 }
 
-void PyModuleRunner::log(int level, const std::string &record)
+void PyModuleRunner::log(const std::string &record)
 {
 #undef dout_prefix
-#define dout_prefix *_dout << "mgr[" << get_name() << "] "
-  dout(ceph::dout::need_dynamic(level)) << record << dendl;
+#define dout_prefix *_dout
+  dout(0) << record << dendl;
 #undef dout_prefix
 #define dout_prefix *_dout << "mgr " << __func__ << " "
 }

src/mgr/PyModuleRunner.h

@@ -54,7 +54,7 @@ class PyModuleRunner
 public:
   int serve();
   void shutdown();
-  void log(int level, const std::string &record);
+  void log(const std::string &record);
 
   const char *get_thread_name() const
   {

src/pybind/mgr/dashboard/HACKING.rst

@@ -1175,16 +1175,18 @@ How to access the manager module instance from a controller?
 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 
 We provide the manager module instance as a global variable that can be
-imported in any module. We also provide a logger instance in the same way.
+imported in any module.
 
 Example:
 
 .. code-block:: python
 
+  import logging
   import cherrypy
-  from .. import logger, mgr
+  from .. import mgr
   from ..tools import ApiController, RESTController
 
+  logger = logging.getLogger(__name__)
 
   @ApiController('servers')
   class Servers(RESTController):
@@ -1940,7 +1942,6 @@ In order to create a new plugin, the following steps are required:
 The available Mixins (helpers) are:
 
 - ``CanMgr``: provides the plug-in with access to the ``mgr`` instance under ``self.mgr``.
-- ``CanLog``: provides the plug-in with access to the Ceph Dashboard logger under ``self.log``.
 
 The available Interfaces are:
 
@@ -1983,9 +1984,8 @@ A sample plugin implementation would look like this:
   import cherrypy
 
   @PM.add_plugin
-  class Mute(I.CanMgr, I.CanLog, I.Setupable, I.HasOptions,
-                       I.HasCommands, I.FilterRequest.BeforeHandler,
-                       I.HasControllers):
+  class Mute(I.CanMgr, I.Setupable, I.HasOptions, I.HasCommands,
+                       I.FilterRequest.BeforeHandler, I.HasControllers):
     @PM.add_hook
     def get_options(self):
       return [Option('mute', default=False, type='bool')]
@@ -2024,7 +2024,7 @@ facilitates the basic tasks (Options, Commands, and common Mixins). The previous
 plugin could be rewritten like this:
 
 .. code-block:: python
-  
+
   from . import PLUGIN_MANAGER as PM
   from . import interfaces as I
   from .plugin import SimplePlugin as SP

src/pybind/mgr/dashboard/__init__.py

@@ -9,38 +9,25 @@
 
 
 if 'UNITTEST' not in os.environ:
-    class _LoggerProxy(object):
-        def __init__(self):
-            self._logger = None
-
-        def __getattr__(self, item):
-            if self._logger is None:
-                raise AttributeError("logger not initialized")
-            return getattr(self._logger, item)
-
     class _ModuleProxy(object):
         def __init__(self):
             self._mgr = None
 
         def init(self, module_inst):
-            global logger
             self._mgr = module_inst
-            logger._logger = self._mgr._logger
 
         def __getattr__(self, item):
             if self._mgr is None:
                 raise AttributeError("global manager module instance not initialized")
             return getattr(self._mgr, item)
 
     mgr = _ModuleProxy()
-    logger = _LoggerProxy()
 
     # DO NOT REMOVE: required for ceph-mgr to load a module
     from .module import Module, StandbyModule  # noqa: F401
 else:
     import logging
     logging.basicConfig(level=logging.DEBUG)
-    logger = logging.getLogger(__name__)
     logging.root.handlers[0].setLevel(logging.DEBUG)
     os.environ['PATH'] = '{}:{}'.format(os.path.abspath('../../../../build/bin'),
                                         os.environ['PATH'])

src/pybind/mgr/dashboard/conftest.py

@@ -1,9 +1,9 @@
 import sys
 
 try:
-    from mock import Mock
+    from mock import Mock, patch
 except ImportError:
-    from unittest.mock import Mock
+    from unittest.mock import Mock, patch
 
 
 class MockRadosError(Exception):
@@ -24,3 +24,16 @@ def pytest_configure(config):
         'rbd': Mock(),
         'cephfs': Mock(),
     })
+
+    # we need the following patches to fix the issue of multiple inheritance when
+    # one of the base classes is being mocked.
+    # Error example:
+    # TypeError: metaclass conflict: the metaclass of a derived class must be a (non-strict) \
+    # subclass of the metaclasses of all its bases
+    class _BaseMgrModule:
+        pass
+
+    patcher = patch("ceph_module.BaseMgrStandbyModule", new=_BaseMgrModule)
+    patcher.start()
+    patcher = patch("ceph_module.BaseMgrModule", new=_BaseMgrModule)
+    patcher.start()

src/pybind/mgr/dashboard/controllers/__init__.py

@@ -6,6 +6,7 @@
 import importlib
 import inspect
 import json
+import logging
 import os
 import pkgutil
 import re
@@ -17,7 +18,6 @@
 # pylint: disable=wrong-import-position
 import cherrypy
 
-from .. import logger
 from ..security import Scope, Permission
 from ..tools import wraps, getargspec, TaskManager, get_request_body_params
 from ..exceptions import ScopeNotValid, PermissionNotValid
@@ -133,8 +133,6 @@ def __call__(self, cls):
 class Controller(object):
     def __init__(self, path, base_url=None, security_scope=None, secure=True):
         if security_scope and not Scope.valid_scope(security_scope):
-            logger.debug("Invalid security scope name: %s\n Possible values: "
-                         "%s", security_scope, Scope.all_scopes())
             raise ScopeNotValid(security_scope)
         self.path = path
         self.base_url = base_url
@@ -254,19 +252,20 @@ def Proxy(path=None):  # noqa: N802
 
 
 def load_controllers():
+    logger = logging.getLogger('controller.load')
     # setting sys.path properly when not running under the mgr
     controllers_dir = os.path.dirname(os.path.realpath(__file__))
     dashboard_dir = os.path.dirname(controllers_dir)
     mgr_dir = os.path.dirname(dashboard_dir)
-    logger.debug("LC: controllers_dir=%s", controllers_dir)
-    logger.debug("LC: dashboard_dir=%s", dashboard_dir)
-    logger.debug("LC: mgr_dir=%s", mgr_dir)
+    logger.debug("controllers_dir=%s", controllers_dir)
+    logger.debug("dashboard_dir=%s", dashboard_dir)
+    logger.debug("mgr_dir=%s", mgr_dir)
     if mgr_dir not in sys.path:
         sys.path.append(mgr_dir)
 
     controllers = []
     mods = [mod for _, mod, _ in pkgutil.iter_modules([controllers_dir])]
-    logger.debug("LC: mods=%s", mods)
+    logger.debug("mods=%s", mods)
     for mod_name in mods:
         mod = importlib.import_module('.controllers.{}'.format(mod_name),
                                       package='dashboard')
@@ -320,6 +319,7 @@ def generate_controller_routes(endpoint, mapper, base_url):
 
     url = "{}{}".format(base_url, endp_url)
 
+    logger = logging.getLogger('controller')
     logger.debug("Mapped [%s] to %s:%s restricted to %s",
                  url, ctrl_class.__name__, endpoint.action,
                  endpoint.method)
@@ -357,6 +357,7 @@ def generate_routes(url_prefix):
         parent_urls.add(generate_controller_routes(endpoint, mapper,
                                                    "{}".format(url_prefix)))
 
+    logger = logging.getLogger('controller')
     logger.debug("list of parent paths: %s", parent_urls)
     return mapper, parent_urls
 
@@ -586,6 +587,7 @@ def __repr__(self):
                                                  self.action)
 
     def __init__(self):
+        logger = logging.getLogger('controller')
         logger.info('Initializing controller: %s -> %s',
                     self.__class__.__name__, self._cp_path_)
         super(BaseController, self).__init__()
@@ -897,6 +899,7 @@ def _set_func_permissions(func, permissions):
 
     for perm in permissions:
         if not Permission.valid_permission(perm):
+            logger = logging.getLogger('controller.set_func_perms')
             logger.debug("Invalid security permission: %s\n "
                          "Possible values: %s", perm,
                          Permission.all_permissions())

src/pybind/mgr/dashboard/controllers/auth.py

@@ -1,14 +1,18 @@
 # -*- coding: utf-8 -*-
 from __future__ import absolute_import
 
+import logging
 import cherrypy
 
 from . import ApiController, RESTController
-from .. import logger, mgr
+from .. import mgr
 from ..exceptions import DashboardException
 from ..services.auth import AuthManager, JwtManager
 
 
+logger = logging.getLogger('controllers.auth')
+
+
 @ApiController('/auth', secure=False)
 class Auth(RESTController):
     """