mgr: forward the root-logger fallback at the record's own level

ceph_module.mgr_log() emitted every record at dout(0): a record either
passed the Python-side gate and went unconditionally to both the log
file and the in-memory recent buffer, or never reached the C++ log at
all.  The two-level debug_mgr semantics (file level / memory level)
never applied, so capturing third-party DEBUG logs meant sending each
record to the log file and a log_max_recent slot; with the kubernetes
client logging multi-megabyte HTTP response bodies at DEBUG, the
recent buffer alone could grow to tens of gigabytes.

Pass the record's level through mgr_log() and emit at the mapped ceph
level: CRITICAL/ERROR at 0, WARNING at 1, INFO at 2, DEBUG at 20.
INFO maps to 2 so it stays visible in the log file at the default
debug_mgr=2/5; DEBUG maps to 20 so floods are dropped there, while
debug_mgr=2/20 captures third-party DEBUG in the in-memory buffer
without touching the log file.  The Python-side gate follows the
higher of the two debug_mgr levels so memory-only records still
reach the C++ side.

Fixes: https://tracker.ceph.com/issues/77633
Signed-off-by: Kefu Chai <k.chai@proxmox.com>

diff --git a/src/mgr/PyModule.cc b/src/mgr/PyModule.cc
index 8e152e248e4c6f43979cd3cf04a10485cbf5cec2..16bbd7a8a06a3686905e08a609e539ef47e0a6f0 100644 (file)
--- a/src/mgr/PyModule.cc
+++ b/src/mgr/PyModule.cc
@@ -300,17 +300,22 @@ PyObject* PyModule::init_ceph_logger()
 }
 
 // module-independent sink for the Python root-logger fallback; the Python
-// side filters and formats, this just emits like PyModuleRunner::log()
+// side maps the record's level to a ceph debug level, so the usual
+// subsystem gating applies per record
 static PyObject*
 ceph_mgr_log(PyObject *self, PyObject *args)
 {
+  int level = 0;
   char *record = nullptr;
-  if (!PyArg_ParseTuple(args, "s:mgr_log", &record)) {
+  if (!PyArg_ParseTuple(args, "is:mgr_log", &level, &record)) {
     return nullptr;
   }
+  if (level < 0) {
+    level = 0;
+  }
 #undef dout_prefix
 #define dout_prefix *_dout
-  dout(0) << record << dendl;
+  dout(ceph::dout::need_dynamic(level)) << record << dendl;
 #undef dout_prefix
 #define dout_prefix *_dout << "mgr[py] "
   Py_RETURN_NONE;
@@ -320,7 +325,7 @@ PyObject* PyModule::init_ceph_module()
 {
   static PyMethodDef module_methods[] = {
     {"mgr_log", ceph_mgr_log, METH_VARARGS,
-     "log a preformatted record to the mgr daemon log"},
+     "log a preformatted record to the mgr daemon log at a debug level"},
     {nullptr, nullptr, 0, nullptr}
   };
   static PyModuleDef ceph_module_def = {

diff --git a/src/pybind/mgr/ceph_module.pyi b/src/pybind/mgr/ceph_module.pyi
index 22a353e9f3e9799688a0764c60c2a43e87a3451c..00af28e7e5980454b76c19f35e3bb018a4575561 100644 (file)
--- a/src/pybind/mgr/ceph_module.pyi
+++ b/src/pybind/mgr/ceph_module.pyi
@@ -10,7 +10,7 @@ except ImportError:
         pass
 
 
-def mgr_log(record: str) -> None: ...
+def mgr_log(level: int, record: str) -> None: ...
 
 
 class BasePyOSDMap(object):

diff --git a/src/pybind/mgr/mgr_module.py b/src/pybind/mgr/mgr_module.py
index d91ee7140335ae379acad3b0ab1e7c6c5edf3ff8..bae163999e566235e183b10c21385de4c1f51e94 100644 (file)
--- a/src/pybind/mgr/mgr_module.py
+++ b/src/pybind/mgr/mgr_module.py
@@ -712,9 +712,23 @@ class MgrRootHandler(logging.Handler):
             "[mgr %(levelname)-4s %(name)s] %(message)s"
         ))
 
+    @staticmethod
+    def _ceph_log_level(levelno: int) -> int:
+        # inverse of _ceph_log_level_to_python.  INFO -> 2 keeps it in the
+        # log file at the default debug_mgr=2/5; DEBUG -> 20 keeps floods
+        # out unless raised, e.g. 2/20 for in-memory capture only.
+        if levelno >= logging.ERROR:
+            return 0
+        if levelno >= logging.WARNING:
+            return 1
+        if levelno >= logging.INFO:
+            return 2
+        return 20
+
     def emit(self, record: logging.LogRecord) -> None:
         if record.levelno >= self.level:
-            ceph_module.mgr_log(self.format(record))
+            ceph_module.mgr_log(self._ceph_log_level(record.levelno),
+                                self.format(record))
 
 
 class ClusterLogHandler(logging.Handler):
@@ -807,6 +821,25 @@ class MgrModuleLoggingMixin(object):
         return next((h for h in root.handlers
                      if isinstance(h, MgrRootHandler)), None)
 
+    @staticmethod
+    def _debug_mgr_gather_to_python(log_level: str) -> str:
+        # records are emitted at their own mapped levels, so forward
+        # everything the C++ side could gather: gate on the higher of the
+        # two debug_mgr levels, not just the file level
+        gather = 0
+        if log_level:
+            try:
+                gather = max(int(level) for level in log_level.split("/", 1))
+            except ValueError:
+                pass
+        if gather >= 20:
+            return "DEBUG"
+        if gather >= 2:
+            return "INFO"
+        if gather >= 1:
+            return "WARNING"
+        return "ERROR"
+
     def _set_log_level(self,
                        mgr_level: str,
                        module_level: str,
@@ -816,7 +849,7 @@ class MgrModuleLoggingMixin(object):
         # even when the module level is unchanged
         root_handler = self._mgr_root_handler()
         if root_handler is not None:
-            root_handler.setLevel(self._ceph_log_level_to_python(mgr_level))
+            root_handler.setLevel(self._debug_mgr_gather_to_python(mgr_level))
 
         module_level = module_level.upper() if module_level else ''
         if not self._module_level: