LSST Applications  21.0.0-147-g0e635eb1+1acddb5be5,22.0.0+052faf71bd,22.0.0+1ea9a8b2b2,22.0.0+6312710a6c,22.0.0+729191ecac,22.0.0+7589c3a021,22.0.0+9f079a9461,22.0.1-1-g7d6de66+b8044ec9de,22.0.1-1-g87000a6+536b1ee016,22.0.1-1-g8e32f31+6312710a6c,22.0.1-10-gd060f87+016f7cdc03,22.0.1-12-g9c3108e+df145f6f68,22.0.1-16-g314fa6d+c825727ab8,22.0.1-19-g93a5c75+d23f2fb6d8,22.0.1-19-gb93eaa13+aab3ef7709,22.0.1-2-g8ef0a89+b8044ec9de,22.0.1-2-g92698f7+9f079a9461,22.0.1-2-ga9b0f51+052faf71bd,22.0.1-2-gac51dbf+052faf71bd,22.0.1-2-gb66926d+6312710a6c,22.0.1-2-gcb770ba+09e3807989,22.0.1-20-g32debb5+b8044ec9de,22.0.1-23-gc2439a9a+fb0756638e,22.0.1-3-g496fd5d+09117f784f,22.0.1-3-g59f966b+1e6ba2c031,22.0.1-3-g849a1b8+f8b568069f,22.0.1-3-gaaec9c0+c5c846a8b1,22.0.1-32-g5ddfab5d3+60ce4897b0,22.0.1-4-g037fbe1+64e601228d,22.0.1-4-g8623105+b8044ec9de,22.0.1-5-g096abc9+d18c45d440,22.0.1-5-g15c806e+57f5c03693,22.0.1-7-gba73697+57f5c03693,master-g6e05de7fdc+c1283a92b8,master-g72cdda8301+729191ecac,w.2021.39
LSST Data Management Base Package
PyLogAppender.cc
Go to the documentation of this file.
1 /*
2  * This file is part of log.
3  *
4  * Developed for the LSST Data Management System.
5  * This product includes software developed by the LSST Project
6  * (https://www.lsst.org).
7  * See the COPYRIGHT file at the top-level directory of this distribution
8  * for details of code ownership.
9  *
10  * This program is free software: you can redistribute it and/or modify
11  * it under the terms of the GNU General Public License as published by
12  * the Free Software Foundation, either version 3 of the License, or
13  * (at your option) any later version.
14  *
15  * This program is distributed in the hope that it will be useful,
16  * but WITHOUT ANY WARRANTY; without even the implied warranty of
17  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
18  * GNU General Public License for more details.
19  *
20  * You should have received a copy of the GNU General Public License
21  * along with this program. If not, see <https://www.gnu.org/licenses/>.
22  */
23 
24 #include <algorithm>
25 #include <memory>
26 #include <stdexcept>
27 
28 #include "./PyLogAppender.h"
29 #include "log4cxx/patternlayout.h"
30 #include "log4cxx/helpers/stringhelper.h"
31 
32 // macro below dows not work without this using directive
33 // (and it breaks if placed inside namespaces)
35 IMPLEMENT_LOG4CXX_OBJECT(PyLogAppender)
36 
37 using namespace log4cxx::helpers;
38 
39 namespace {
40 
41 // GIL wrapper class
42 class GilGuard {
43 public:
44 
45  GilGuard() : gil_state(PyGILState_Ensure()) {}
46 
47  ~GilGuard() { PyGILState_Release(gil_state); }
48 
49 private:
50  PyGILState_STATE gil_state;
51 };
52 
56 std::string reraise(std::string const& message) {
57  lsst::log::detail::PyObjectPtr ptype, pvalue, ptraceback;
58  PyErr_Fetch(&ptype.get(), &pvalue.get(), &ptraceback.get());
59 
60  std::string exc_msg = message;
61  if (pvalue != nullptr or ptype != nullptr) {
62  lsst::log::detail::PyObjectPtr exc_str(PyObject_Str(pvalue != nullptr ? pvalue : ptype));
63  exc_msg += ": ";
64  exc_msg += PyUnicode_AsUTF8(exc_str);
65  }
66 
67  throw std::runtime_error(exc_msg);
68 }
69 
70 // Maximum size of the logger name cache
71 unsigned const MAX_LRU_CACHE_SIZE = 32;
72 
73 }
74 
75 namespace lsst::log::detail {
76 
77 PyLogAppender::PyLogAppender() {
78 
79  GilGuard gil_guard;
80 
81  PyObjectPtr logging(PyImport_ImportModule("logging"));
82  if (logging == nullptr) {
83  ::reraise("ImportError: Failed to import Python logging module");
84  }
85  _getLogger = PyObject_GetAttrString(logging, "getLogger");
86  if (_getLogger == nullptr) {
87  ::reraise("AttributeError: logging.getLogger method does not exist");
88  }
89 
90  PyObjectPtr lsstlog_module(PyImport_ImportModule("lsst.log"));
91  if (lsstlog_module == nullptr) {
92  ::reraise("ImportError: Failed to import lsst.log module");
93  }
94  _mdc_class = PyObject_GetAttrString(lsstlog_module, "MDCDict");
95  if (_mdc_class == nullptr) {
96  ::reraise("AttributeError: lsst.log.MDCDict class does not exist");
97  }
98 }
99 
100 void PyLogAppender::append(const spi::LoggingEventPtr& event, log4cxx::helpers::Pool& p) {
101 
102  // logger name, UTF-8 encoded
103  std::string logger_name;
104  log4cxx::helpers::Transcoder::encodeUTF8(event->getLoggerName(), logger_name);
105  int const level = event->getLevel()->toInt();
106  int const pyLevel = level / 1000;
107 
108  // Check logger name in cache first, this does not need GIL but needs
109  // synchronization
111  {
112  std::lock_guard<std::mutex> lock(_cache_mutex);
113  auto cache_iter = _cache.find(logger_name);
114  if (cache_iter != _cache.end()) {
115  // use it, age is updated later
116  logger = cache_iter->second.logger;
117  }
118  }
119 
120  // Need Python at this point
121  GilGuard gil_guard;
122 
123  if (logger == nullptr) {
124  // was not found in cache get one from Python
125  if (logger_name == "root") {
126  logger = PyObject_CallFunction(_getLogger, nullptr);
127  } else {
128  logger = PyObject_CallFunction(_getLogger, "s", logger_name.c_str());
129  }
130  }
131  if (logger == nullptr) {
132  ::reraise("Failed to retrieve Python logger \"" + logger_name + "\"");
133  } else {
134  // remember it in cache
135  std::lock_guard<std::mutex> lock(_cache_mutex);
136  _cache.emplace(logger_name, LRUEntry({logger, _lru_age ++}));
137  while (_cache.size() > ::MAX_LRU_CACHE_SIZE) {
138  // find oldest element and remove
139  auto iter = std::min_element(
140  _cache.begin(), _cache.end(),
141  [](const LRUCache::value_type& lhs, const LRUCache::value_type& rhs) {
142  return lhs.second.age < rhs.second.age;
143  }
144  );
145  _cache.erase(iter);
146  }
147  // Age counter could potentially overflow (wrap to 0), reset age for
148  // all cache entries to avoid issues.
149  if (_lru_age == 0) {
150  for (auto& cache_value: _cache) {
151  // give them different but "random" ages
152  cache_value.second.age = _lru_age ++;
153  }
154  }
155  }
156 
157  // before doing anything check logging level
158  PyObjectPtr py_is_enabled(PyObject_CallMethod(logger, "isEnabledFor", "i", pyLevel));
159  if (py_is_enabled == nullptr) {
160  ::reraise("Failure when calling logger.isEnabledFor() method");
161  }
162  if (not PyObject_IsTrue(py_is_enabled)) {
163  return;
164  }
165 
166  // collect all necessary info
167  auto& loc = event->getLocationInformation();
168  std::string file_name;
169  if (loc.getFileName() != nullptr) {
170  file_name = loc.getFileName();
171  }
172  int const lineno = loc.getLineNumber();
173 
174  // if layout is defined then use formatted message
175  std::string message;
176  if (this->layout) {
177  LogString msg;
178  this->layout->format(msg, event, p);
179  // get rid of trailing new-line, just in case someone uses %n in format
180  if (not msg.empty() and msg.back() == '\n') {
181  msg.pop_back();
182  }
183  log4cxx::helpers::Transcoder::encodeUTF8(msg, message);
184  } else {
185  log4cxx::helpers::Transcoder::encodeUTF8(event->getMessage(), message);
186  }
187 
188  // record = logger.makeRecord(name, level, fn, lno, msg, args, exc_info,
189  // func=None, extra=None, sinfo=None)
190  // I would like to pass MDC as an `extra` argument but that does not
191  // work reliably in case we want to override record factory.
192  PyObjectPtr record(PyObject_CallMethod(logger, "makeRecord", "sisisOO",
193  logger_name.c_str(),
194  pyLevel,
195  file_name.c_str(),
196  lineno,
197  message.c_str(),
198  Py_None,
199  Py_None));
200  if (record == nullptr) {
201  ::reraise("Failed to create LogRecord instance");
202  }
203 
204  // Record should already have an `MDC` attribute added by a record factory,
205  // and it may be pre-filled with some info by the same factory. Here we
206  // assume that if it already exists then it is dict-like, if it does not
207  // we add this attribute as lsst.log.MDCDict instance (which is a dict with
208  // some extra niceties).
209 
210  // mdc = getattr(record, "MDC")
211  PyObjectPtr mdc(PyObject_GetAttrString(record, "MDC"));
212  if (mdc == nullptr) {
213  PyErr_Clear();
214  // mdc = lsst.log.MDCDict()
215  mdc = PyObject_CallObject(_mdc_class, nullptr);
216  if (mdc == nullptr) {
217  ::reraise("Failed to make MDCDict instance");
218  }
219  // record.MDC = mdc
220  if (PyObject_SetAttrString(record, "MDC", mdc) == -1) {
221  ::reraise("Failed to set LogRecord MDC attribute");
222  }
223  }
224 
225  // Copy MDC to dict, for key in getMDCKeySet(): mdc[key] = event.getMDC(key)
226  for (auto& mdc_key: event->getMDCKeySet()) {
227  std::string key, value;
228  log4cxx::helpers::Transcoder::encodeUTF8(mdc_key, key);
229  log4cxx::LogString mdc_value;
230  event->getMDC(mdc_key, mdc_value);
231  log4cxx::helpers::Transcoder::encodeUTF8(mdc_value, value);
232  PyObjectPtr py_value(PyUnicode_FromStringAndSize(value.data(), value.size()));
233  PyObjectPtr py_key(PyUnicode_FromStringAndSize(key.data(), key.size()));
234  if (PyObject_SetItem(mdc, py_key, py_value) == -1) {
235  // it is probably not a dictionary
236  ::reraise("Failed to update MDC dictionary");
237  }
238  }
239 
240  // logger.handle(record)
241  PyObjectPtr res(PyObject_CallMethod(logger, "handle", "O", record.get()));
242  if (res == nullptr) {
243  ::reraise("Logger failed to handle LogRecord");
244  }
245 }
246 
247 void PyLogAppender::close() {
248 }
249 
250 bool PyLogAppender::requiresLayout() const {
251  return false;
252 }
253 
254 void PyLogAppender::setOption(const LogString &option, const LogString &value) {
255 
256  if (StringHelper::equalsIgnoreCase(option, LOG4CXX_STR("MESSAGEPATTERN"),
257  LOG4CXX_STR("messagepattern"))) {
258  setLayout(LayoutPtr(new PatternLayout(value)));
259  } else {
260  AppenderSkeleton::setOption(option, value);
261  }
262 }
263 
264 } // namespace lsst::log::detail
T c_str(T... args)
This class defines special log4cxx appender which "appends" log messages to Python logging.
Definition: PyLogAppender.h:58
Smart pointer class for PyObject instances.
Definition: PyObjectPtr.h:37
T data(T... args)
T min_element(T... args)
std::shared_ptr< FrameSet > append(FrameSet const &first, FrameSet const &second)
Construct a FrameSet that performs two transformations in series.
Definition: functional.cc:33
T pop_back(T... args)
T size(T... args)