logging.cpp 10.1 KB
Newer Older
1
2
3
4
5
6
7
/**
 * @author Andre Anjos <andre.anjos@idiap.ch>
 * @date Fri 18 Oct 19:21:57 2013
 *
 * @brief Bindings to re-inject C++ messages into the Python logging module
 */

8
#define BOB_CORE_LOGGING_MODULE
9
#include <bob.core/api.h>
10

11
12
13
14
15
#ifdef NO_IMPORT_ARRAY
#undef NO_IMPORT_ARRAY
#endif
#include <bob.blitz/capi.h>
#include <bob.blitz/cleanup.h>
16
#include <bob.extension/documentation.h>
17

18
19
20
21
#include <boost/make_shared.hpp>

#define PYTHON_LOGGING_DEBUG 0

André Anjos's avatar
André Anjos committed
22
#if PYTHON_LOGGING_DEBUG != 0
André Anjos's avatar
André Anjos committed
23
24
#include <boost/algorithm/string.hpp>
static boost::iostreams::stream<bob::core::AutoOutputDevice> static_log("stdout");
André Anjos's avatar
André Anjos committed
25
#endif
26

27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
/**
 * Free standing functions for the module's C-API
 */
int PyBobCoreLogging_APIVersion = BOB_CORE_API_VERSION;

boost::iostreams::stream<bob::core::AutoOutputDevice>& PyBobCoreLogging_Debug() {
  return bob::core::debug;
}

boost::iostreams::stream<bob::core::AutoOutputDevice>& PyBobCoreLogging_Info() {
  return bob::core::info;
}

boost::iostreams::stream<bob::core::AutoOutputDevice>& PyBobCoreLogging_Warn() {
  return bob::core::warn;
}

boost::iostreams::stream<bob::core::AutoOutputDevice>& PyBobCoreLogging_Error() {
  return bob::core::error;
}
47

48
49
/**
 * Objects of this class are able to redirect the data injected into a
André Anjos's avatar
André Anjos committed
50
51
52
53
 * boost::iostreams::stream<bob::core::AutoOutputDevice> to be re-injected in a
 * given python callable object, that is given upon construction. The key idea
 * is that you feed in something like logging.debug to the constructor, for the
 * debug stream, logging.info for the info stream and so on.
54
55
56
 */
struct PythonLoggingOutputDevice: public bob::core::OutputDevice {

André Anjos's avatar
André Anjos committed
57
58
  PyObject* m_logger; ///< to stream the data out
  PyObject* m_name; ///< the name of the method to call on the object
59
60
61
62

  /**
   * Builds a new OutputDevice from a given callable
   *
André Anjos's avatar
André Anjos committed
63
64
   * @param logger Is a logging.logger-style object.
   * @param name Is the name of the method to call for logging.
65
66
67
   *
   * This method is called from Python, so the GIL is on
   */
André Anjos's avatar
André Anjos committed
68
69
70
71
72
  PythonLoggingOutputDevice(PyObject* logger, const char* name):
    m_logger(0), m_name(0)
  {

      if (logger && logger != Py_None) {
73
        m_logger = Py_BuildValue("O", logger);
André Anjos's avatar
André Anjos committed
74
        m_name = Py_BuildValue("s", name);
75
76
77
78
      }

#if   PYTHON_LOGGING_DEBUG != 0
      pthread_t thread_id = pthread_self();
André Anjos's avatar
André Anjos committed
79
      static_log << "(" << std::hex << thread_id << std::dec
80
81
82
83
                 << ") Constructing new PythonLoggingOutputDevice from logger `logging.logger('"
                 << PyString_AsString(PyObject_GetAttrString(m_logger, "name")) << "')."
                 << name << "' (@" << std::hex << m_logger << std::dec
                 << ")" << std::endl;
84
85
86
87
88
#endif

    }

  /**
André Anjos's avatar
André Anjos committed
89
   * D'tor
90
   */
André Anjos's avatar
André Anjos committed
91
  virtual ~PythonLoggingOutputDevice() {
André Anjos's avatar
André Anjos committed
92
93
94
95
96
97
98
#if PYTHON_LOGGING_DEBUG != 0
    pthread_t thread_id = pthread_self();
    const char* _name = "null";
    if (m_logger) {
      _name = PyString_AsString(PyObject_GetAttrString(m_logger, "name"));
    }
    static_log << "(" << std::hex << thread_id << std::dec
99
100
               << ") Destroying PythonLoggingOutputDevice with logger `" << _name
               << "' (" << std::hex << m_logger << std::dec << ")" << std::endl;
101
#endif
André Anjos's avatar
André Anjos committed
102
    if (m_logger) close();
103
104
105
106
107
108
  }

  /**
   * Closes this stream for good
   */
  virtual void close() {
André Anjos's avatar
André Anjos committed
109
110
111
112
113
114
115
#if PYTHON_LOGGING_DEBUG != 0
    pthread_t thread_id = pthread_self();
    const char* _name = "null";
    if (m_logger) {
      _name = PyString_AsString(PyObject_GetAttrString(m_logger, "name"));
    }
    static_log << "(" << std::hex << thread_id << std::dec
116
117
               << ") Closing PythonLoggingOutputDevice with logger `" << _name
               << "' (" << std::hex << m_logger << std::dec << ")" << std::endl;
André Anjos's avatar
André Anjos committed
118
119
120
121
122
#endif
    Py_XDECREF(m_logger);
    m_logger = 0;
    Py_XDECREF(m_name);
    m_name = 0;
123
124
125
126
127
128
129
130
131
132
133
134
  }

  /**
   * Writes a message to the callable.
   *
   * Because this is called from C++ and, potentially, from other threads of
   * control, it ensures acquisition of the GIL.
   */
  virtual inline std::streamsize write(const char* s, std::streamsize n) {

    auto gil = PyGILState_Ensure();

André Anjos's avatar
André Anjos committed
135
    if (!m_logger || m_logger == Py_None) {
136
137
138
139
140
141
      PyGILState_Release(gil);
      return 0;
    }

#if   PYTHON_LOGGING_DEBUG != 0
    pthread_t thread_id = pthread_self();
André Anjos's avatar
André Anjos committed
142
143
    std::string message(s, n);
    static_log << "(" << std::hex << thread_id << std::dec
144
145
146
147
               << ") Processing message `" << boost::algorithm::trim_right_copy(message)
               << "' (size = " << n << ") with method `logging.logger('"
               << PyString_AsString(PyObject_GetAttrString(m_logger, "name")) << "')."
               << PyString_AsString(m_name) << "'" << std::endl;
148
149
#endif

André Anjos's avatar
André Anjos committed
150
    int len = n;
151
152
    while (std::isspace(s[len-1])) len -= 1;

André Anjos's avatar
André Anjos committed
153
    PyObject* value = Py_BuildValue("s#", s, len);
154
    auto value_ = make_safe(value);
André Anjos's avatar
André Anjos committed
155
    PyObject* result = PyObject_CallMethodObjArgs(m_logger, m_name, value, 0);
156
    auto result_ = make_xsafe(result);
André Anjos's avatar
André Anjos committed
157

158
159
160
161
    if (!result) len = 0;

    PyGILState_Release(gil);

André Anjos's avatar
André Anjos committed
162
    return n;
163
164
165
166
167
  }

};


168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
static auto reset_doc = bob::extension::FunctionDoc(
  "reset",
  "Resets the standard C++ logging devices, or sets it to the given callable",
  "This function allows you to manipulate the sinks for messages emitted in C++, using Python callables. "
  "The first variant (without parameters) will reset all logging output to :py:data:`sys.stderr`. "
  "The second variant will reset the given logger to the given callable. "
  "If ``stream`` is not specified, it resets all loggers.\n\n"
  "This function raises a :py:exc:`ValueError` in case of problems setting or resetting any of the streams."
)
.add_prototype("")
.add_prototype("callable, [stream]")
.add_parameter("callable", "callable", "A python callable that receives an ``str`` and dumps messages to the desired output channel")
.add_parameter("stream", "one of ('debug', 'info', warn', 'error')", "[optional] If specified, only the given logger is send to the given callable. Otherwise all loggers are reset to that callable.")
;
static int set_stream(boost::iostreams::stream<bob::core::AutoOutputDevice>& s, PyObject* o, const char* n) {
183
184
  // if no argument or None, write everything else to stderr
  if (!o || o == Py_None) {
André Anjos's avatar
André Anjos committed
185
186
187
#if   PYTHON_LOGGING_DEBUG != 0
    pthread_t thread_id = pthread_self();
    static_log << "(" << std::hex << thread_id << std::dec
188
               << ") Resetting stream `" << n << "' to stderr" << std::endl;
André Anjos's avatar
André Anjos committed
189
#endif
André Anjos's avatar
André Anjos committed
190
    s.close();
André Anjos's avatar
André Anjos committed
191
    s.open("stderr");
192
193
194
    return 1;
  }

André Anjos's avatar
André Anjos committed
195
196
  if (PyObject_HasAttrString(o, n)) {
    PyObject* callable = PyObject_GetAttrString(o, n);
197
    auto callable_ = make_safe(callable);
André Anjos's avatar
André Anjos committed
198
199
    if (callable && PyCallable_Check(callable)) {
#if   PYTHON_LOGGING_DEBUG != 0
200
201
202
203
      pthread_t thread_id = pthread_self();
      static_log << "(" << std::hex << thread_id << std::dec
                 << ") Setting stream `" << n << "' to logger at " << std::hex
                 << o << std::dec << std::endl;
André Anjos's avatar
André Anjos committed
204
205
206
207
208
209
#endif

      s.close();
      s.open(boost::make_shared<PythonLoggingOutputDevice>(o, n));
      return 1;
    }
210
211
212
  }

  // if you get to this point, set an error
André Anjos's avatar
André Anjos committed
213
  PyErr_Format(PyExc_ValueError, "argument to set stream `%s' needs to be either None or an object with a callable named `%s'", n, n);
214
215
216
  return 0;
}

André Anjos's avatar
André Anjos committed
217
static PyObject* reset(PyObject*, PyObject* args, PyObject* kwds) {
218
219
BOB_TRY
  char** kwlist = reset_doc.kwlist(1);
220

221
222
  PyObject* callable = 0;
  const char* stream = 0;
223

224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
  if (!PyArg_ParseTupleAndKeywords(args, kwds, "|Os", kwlist, &callable, &stream)) return 0;

  if (!stream){
    // reset all streams to either stderr or the given callable
    if (!set_stream(bob::core::debug, callable, "debug")) return 0;
    if (!set_stream(bob::core::info, callable, "info")) return 0;
    if (!set_stream(bob::core::warn, callable, "warn")) return 0;
    if (!set_stream(bob::core::error, callable, "error")) return 0;
  } else {
    if (strcmp(stream, "debug") && strcmp(stream, "info") && strcmp(stream, "warn") && strcmp(stream, "error")){
      PyErr_Format(PyExc_ValueError, "If given, the parameter 'stream' needs to be one of ('debug', 'info', warn', 'error), not %s", stream);
      return 0;
    }
    if (!set_stream(bob::core::error, callable, stream)) return 0;
  }
239
240

  Py_RETURN_NONE;
241
BOB_CATCH_FUNCTION("reset", 0)
242
243
244
245
246
247
248
249
}

/**************************
 * Testing Infrastructure *
 **************************/



André Anjos's avatar
André Anjos committed
250
static PyMethodDef module_methods[] = {
251
    {
252
      reset_doc.name(),
André Anjos's avatar
André Anjos committed
253
      (PyCFunction)reset,
254
      METH_VARARGS|METH_KEYWORDS,
255
      reset_doc.doc()
256
257
258
259
    },
    {0}  /* Sentinel */
};

André Anjos's avatar
André Anjos committed
260
261
262
263
264
PyDoc_STRVAR(module_docstr, "C++ logging handling");

#if PY_VERSION_HEX >= 0x03000000
static PyModuleDef module_definition = {
  PyModuleDef_HEAD_INIT,
André Anjos's avatar
André Anjos committed
265
  BOB_EXT_MODULE_NAME,
André Anjos's avatar
André Anjos committed
266
267
  module_docstr,
  -1,
268
  module_methods,
André Anjos's avatar
André Anjos committed
269
270
271
272
  0, 0, 0, 0
};
#endif

André Anjos's avatar
André Anjos committed
273
static PyObject* create_module (void) {
274

André Anjos's avatar
André Anjos committed
275
276
# if PY_VERSION_HEX >= 0x03000000
  PyObject* m = PyModule_Create(&module_definition);
277
278
  auto m_ = make_xsafe(m);
  const char* ret = "O";
André Anjos's avatar
André Anjos committed
279
# else
André Anjos's avatar
André Anjos committed
280
  PyObject* m = Py_InitModule3(BOB_EXT_MODULE_NAME, module_methods, module_docstr);
281
  const char* ret = "N";
André Anjos's avatar
André Anjos committed
282
# endif
André Anjos's avatar
André Anjos committed
283
  if (!m) return 0;
284

285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
  static void* PyBobCoreLogging_API[PyBobCoreLogging_API_pointers];

  /* exhaustive list of C APIs */
  PyBobCoreLogging_API[PyBobCoreLogging_APIVersion_NUM] = (void *)&PyBobCoreLogging_APIVersion;

  /*********************************
   * Bindings for bob.core.logging *
   *********************************/

  PyBobCoreLogging_API[PyBobCoreLogging_Debug_NUM] = (void *)PyBobCoreLogging_Debug;

  PyBobCoreLogging_API[PyBobCoreLogging_Info_NUM] = (void *)PyBobCoreLogging_Info;

  PyBobCoreLogging_API[PyBobCoreLogging_Warn_NUM] = (void *)PyBobCoreLogging_Warn;

  PyBobCoreLogging_API[PyBobCoreLogging_Error_NUM] = (void *)PyBobCoreLogging_Error;

#if PY_VERSION_HEX >= 0x02070000

  /* defines the PyCapsule */

  PyObject* c_api_object = PyCapsule_New((void *)PyBobCoreLogging_API,
      BOB_EXT_MODULE_PREFIX "." BOB_EXT_MODULE_NAME "._C_API", 0);

#else

  PyObject* c_api_object = PyCObject_FromVoidPtr((void *)PyBobCoreLogging_API, 0);

#endif

  if (c_api_object) PyModule_AddObject(m, "_C_API", c_api_object);

317
318
  /* imports dependencies */
  if (import_bob_blitz() < 0) return 0;
André Anjos's avatar
André Anjos committed
319

320
  return Py_BuildValue(ret, m);
321
}
André Anjos's avatar
André Anjos committed
322

André Anjos's avatar
André Anjos committed
323
PyMODINIT_FUNC BOB_EXT_ENTRY_NAME (void) {
André Anjos's avatar
André Anjos committed
324
325
326
327
328
# if PY_VERSION_HEX >= 0x03000000
  return
# endif
    create_module();
}