res_pjproject: Add ability to map pjproject log levels to Asterisk log levels
[asterisk/asterisk.git] / res / res_pjproject.c
1 /*
2  * Asterisk -- An open source telephony toolkit.
3  *
4  * Copyright (C) 2013, Digium, Inc.
5  *
6  * David M. Lee, II <dlee@digium.com>
7  *
8  * See http://www.asterisk.org for more information about
9  * the Asterisk project. Please do not directly contact
10  * any of the maintainers of this project for assistance;
11  * the project provides a web site, mailing lists and IRC
12  * channels for your use.
13  *
14  * This program is free software, distributed under the terms of
15  * the GNU General Public License Version 2. See the LICENSE file
16  * at the top of the source tree.
17  */
18
19 /*! \file
20  *
21  * \brief Bridge PJPROJECT logging to Asterisk logging.
22  * \author David M. Lee, II <dlee@digium.com>
23  *
24  * PJPROJECT logging doesn't exactly match Asterisk logging, but mapping the two is
25  * not too bad. PJPROJECT log levels are identified by a single int. Limits are
26  * not specified by PJPROJECT, but their implementation used 1 through 6.
27  *
28  * The mapping is as follows:
29  *  - 0: LOG_ERROR
30  *  - 1: LOG_ERROR
31  *  - 2: LOG_WARNING
32  *  - 3 and above: equivalent to ast_debug(level, ...) for res_pjproject.so
33  */
34
35 /*** MODULEINFO
36         <depend>pjproject</depend>
37         <support_level>core</support_level>
38  ***/
39
40 /*** DOCUMENTATION
41         <configInfo name="res_pjproject" language="en_US">
42                 <synopsis>pjproject common configuration</synopsis>
43                 <configFile name="pjproject.conf">
44                         <configObject name="log_mappings">
45                                 <synopsis>PJPROJECT to Asterisk Log Level Mapping</synopsis>
46                                 <description><para>Warnings and errors in the pjproject libraries are generally handled
47                                         by Asterisk.  In many cases, Asterisk wouldn't even consider them to
48                                         be warnings or errors so the messages emitted by pjproject directly
49                                         are either superfluous or misleading.  The 'log_mappings'
50                                         object allows mapping the pjproject levels to Asterisk levels, or nothing.
51                                         </para>
52                                         <note><para>The id of this object, as well as its type, must be
53                                         'log_mappings' or it won't be found.</para></note>
54                                 </description>
55                                 <configOption name="type">
56                                         <synopsis>Must be of type 'log_mappings'.</synopsis>
57                                 </configOption>
58                                 <configOption name="asterisk_error" default="0,1">
59                                         <synopsis>A comma separated list of pjproject log levels to map to Asterisk LOG_ERROR.</synopsis>
60                                 </configOption>
61                                 <configOption name="asterisk_warning" default="2">
62                                         <synopsis>A comma separated list of pjproject log levels to map to Asterisk LOG_WARNING.</synopsis>
63                                 </configOption>
64                                 <configOption name="asterisk_notice" default="">
65                                         <synopsis>A comma separated list of pjproject log levels to map to Asterisk LOG_NOTICE.</synopsis>
66                                 </configOption>
67                                 <configOption name="asterisk_debug" default="3,4,5">
68                                         <synopsis>A comma separated list of pjproject log levels to map to Asterisk LOG_DEBUG.</synopsis>
69                                 </configOption>
70                                 <configOption name="asterisk_verbose" default="">
71                                         <synopsis>A comma separated list of pjproject log levels to map to Asterisk LOG_VERBOSE.</synopsis>
72                                 </configOption>
73                         </configObject>
74                 </configFile>
75         </configInfo>
76  ***/
77
78 #include "asterisk.h"
79
80 ASTERISK_REGISTER_FILE()
81
82 #include <stdarg.h>
83 #include <pjlib.h>
84 #include <pjsip.h>
85 #include <pj/log.h>
86
87 #include "asterisk/logger.h"
88 #include "asterisk/module.h"
89 #include "asterisk/cli.h"
90 #include "asterisk/res_pjproject.h"
91 #include "asterisk/vector.h"
92 #include "asterisk/sorcery.h"
93
94 static struct ast_sorcery *pjproject_sorcery;
95 static pj_log_func *log_cb_orig;
96 static unsigned decor_orig;
97
98 static AST_VECTOR(buildopts, char *) buildopts;
99
100 /*! Protection from other log intercept instances.  There can be only one at a time. */
101 AST_MUTEX_DEFINE_STATIC(pjproject_log_intercept_lock);
102
103 struct pjproject_log_intercept_data {
104         pthread_t thread;
105         int fd;
106 };
107
108 static struct pjproject_log_intercept_data pjproject_log_intercept = {
109         .thread = AST_PTHREADT_NULL,
110         .fd = -1,
111 };
112
113 struct log_mappings {
114         /*! Sorcery object details */
115         SORCERY_OBJECT(details);
116         /*! These are all comma-separated lists of pjproject log levels */
117         AST_DECLARE_STRING_FIELDS(
118                 /*! pjproject log levels mapped to Asterisk ERROR */
119                 AST_STRING_FIELD(asterisk_error);
120                 /*! pjproject log levels mapped to Asterisk WARNING */
121                 AST_STRING_FIELD(asterisk_warning);
122                 /*! pjproject log levels mapped to Asterisk NOTICE */
123                 AST_STRING_FIELD(asterisk_notice);
124                 /*! pjproject log levels mapped to Asterisk VERBOSE */
125                 AST_STRING_FIELD(asterisk_verbose);
126                 /*! pjproject log levels mapped to Asterisk DEBUG */
127                 AST_STRING_FIELD(asterisk_debug);
128         );
129 };
130
131 static struct log_mappings *default_log_mappings;
132
133 static struct log_mappings *get_log_mappings(void)
134 {
135         struct log_mappings *mappings;
136
137         mappings = ast_sorcery_retrieve_by_id(pjproject_sorcery, "log_mappings", "log_mappings");
138         if (!mappings) {
139                 return ao2_bump(default_log_mappings);
140         }
141
142         return mappings;
143 }
144
145 #define __LOG_SUPPRESS -1
146
147 static int get_log_level(int pj_level)
148 {
149         RAII_VAR(struct log_mappings *, mappings, get_log_mappings(), ao2_cleanup);
150         unsigned char l;
151
152         if (!mappings) {
153                 return __LOG_ERROR;
154         }
155
156         l = '0' + fmin(pj_level, 9);
157
158         if (strchr(mappings->asterisk_error, l)) {
159                 return __LOG_ERROR;
160         } else if (strchr(mappings->asterisk_warning, l)) {
161                 return __LOG_WARNING;
162         } else if (strchr(mappings->asterisk_notice, l)) {
163                 return __LOG_NOTICE;
164         } else if (strchr(mappings->asterisk_verbose, l)) {
165                 return __LOG_VERBOSE;
166         } else if (strchr(mappings->asterisk_debug, l)) {
167                 return __LOG_DEBUG;
168         }
169
170         return __LOG_SUPPRESS;
171 }
172
173 static void log_forwarder(int level, const char *data, int len)
174 {
175         int ast_level;
176         /* PJPROJECT doesn't provide much in the way of source info */
177         const char * log_source = "pjproject";
178         int log_line = 0;
179         const char *log_func = "<?>";
180         int mod_level;
181
182         if (pjproject_log_intercept.fd != -1
183                 && pjproject_log_intercept.thread == pthread_self()) {
184                 /*
185                  * We are handling a CLI command intercepting PJPROJECT
186                  * log output.
187                  */
188                 ast_cli(pjproject_log_intercept.fd, "%s\n", data);
189                 return;
190         }
191
192         ast_level = get_log_level(level);
193
194         if (ast_level == __LOG_SUPPRESS) {
195                 return;
196         }
197
198         if (ast_level == __LOG_DEBUG) {
199                 /* For levels 3 and up, obey the debug level for res_pjproject */
200                 mod_level = ast_opt_dbg_module ?
201                         ast_debug_get_by_module("res_pjproject") : 0;
202                 if (option_debug < level && mod_level < level) {
203                         return;
204                 }
205         }
206
207         /* PJPROJECT uses indention to indicate function call depth. We'll prepend
208          * log statements with a tab so they'll have a better shot at lining
209          * up */
210         ast_log(ast_level, log_source, log_line, log_func, "\t%s\n", data);
211 }
212
213 static void capture_buildopts_cb(int level, const char *data, int len)
214 {
215         if (strstr(data, "Teluu") || strstr(data, "Dumping")) {
216                 return;
217         }
218
219         AST_VECTOR_ADD_SORTED(&buildopts, ast_strdup(ast_skip_blanks(data)), strcmp);
220 }
221
222 #pragma GCC diagnostic ignored "-Wformat-nonliteral"
223 int ast_pjproject_get_buildopt(char *option, char *format_string, ...)
224 {
225         int res = 0;
226         char *format_temp;
227         int i;
228
229         format_temp = ast_alloca(strlen(option) + strlen(" : ") + strlen(format_string) + 1);
230         sprintf(format_temp, "%s : %s", option, format_string);
231
232         for (i = 0; i < AST_VECTOR_SIZE(&buildopts); i++) {
233                 va_list arg_ptr;
234                 va_start(arg_ptr, format_string);
235                 res = vsscanf(AST_VECTOR_GET(&buildopts, i), format_temp, arg_ptr);
236                 va_end(arg_ptr);
237                 if (res) {
238                         break;
239                 }
240         }
241
242         return res;
243 }
244 #pragma GCC diagnostic warning "-Wformat-nonliteral"
245
246 void ast_pjproject_log_intercept_begin(int fd)
247 {
248         /* Protect from other CLI instances trying to do this at the same time. */
249         ast_mutex_lock(&pjproject_log_intercept_lock);
250
251         pjproject_log_intercept.thread = pthread_self();
252         pjproject_log_intercept.fd = fd;
253 }
254
255 void ast_pjproject_log_intercept_end(void)
256 {
257         pjproject_log_intercept.fd = -1;
258         pjproject_log_intercept.thread = AST_PTHREADT_NULL;
259
260         ast_mutex_unlock(&pjproject_log_intercept_lock);
261 }
262
263 void ast_pjproject_ref(void)
264 {
265         ast_module_ref(ast_module_info->self);
266 }
267
268 void ast_pjproject_unref(void)
269 {
270         ast_module_unref(ast_module_info->self);
271 }
272
273 static char *handle_pjproject_show_buildopts(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
274 {
275         int i;
276
277         switch (cmd) {
278         case CLI_INIT:
279                 e->command = "pjproject show buildopts";
280                 e->usage =
281                         "Usage: pjproject show buildopts\n"
282                         "       Show the compile time config of the pjproject that Asterisk is\n"
283                         "       running against.\n";
284                 return NULL;
285         case CLI_GENERATE:
286                 return NULL;
287         }
288
289         ast_cli(a->fd, "PJPROJECT compile time config currently running against:\n");
290
291         for (i = 0; i < AST_VECTOR_SIZE(&buildopts); i++) {
292                 ast_cli(a->fd, "%s\n", AST_VECTOR_GET(&buildopts, i));
293         }
294
295         return CLI_SUCCESS;
296 }
297
298 static void mapping_destroy(void *object)
299 {
300         struct log_mappings *mappings = object;
301
302         ast_string_field_free_memory(mappings);
303 }
304
305 static void *mapping_alloc(const char *name)
306 {
307         struct log_mappings *mappings = ast_sorcery_generic_alloc(sizeof(*mappings), mapping_destroy);
308         if (!mappings) {
309                 return NULL;
310         }
311         ast_string_field_init(mappings, 128);
312
313         return mappings;
314 }
315
316 static char *handle_pjproject_show_log_mappings(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
317 {
318         struct ast_variable *objset;
319         struct ast_variable *i;
320         struct log_mappings *mappings;
321
322         switch (cmd) {
323         case CLI_INIT:
324                 e->command = "pjproject show log mappings";
325                 e->usage =
326                         "Usage: pjproject show log mappings\n"
327                         "       Show pjproject to Asterisk log mappings\n";
328                 return NULL;
329         case CLI_GENERATE:
330                 return NULL;
331         }
332
333         ast_cli(a->fd, "PJPROJECT to Asterisk log mappings:\n");
334         ast_cli(a->fd, "Asterisk Level   : PJPROJECT log levels\n");
335
336         mappings = get_log_mappings();
337         if (!mappings) {
338                 ast_log(LOG_ERROR, "Unable to retrieve pjproject log_mappings\n");
339                 return CLI_SUCCESS;
340         }
341
342         objset = ast_sorcery_objectset_create(pjproject_sorcery, mappings);
343         if (!objset) {
344                 ao2_ref(mappings, -1);
345                 return CLI_SUCCESS;
346         }
347
348         for (i = objset; i; i = i->next) {
349                 ast_cli(a->fd, "%-16s : %s\n", i->name, i->value);
350         }
351         ast_variables_destroy(objset);
352
353         ao2_ref(mappings, -1);
354         return CLI_SUCCESS;
355 }
356
357 static struct ast_cli_entry pjproject_cli[] = {
358         AST_CLI_DEFINE(handle_pjproject_show_buildopts, "Show the compiled config of the pjproject in use"),
359         AST_CLI_DEFINE(handle_pjproject_show_log_mappings, "Show pjproject to Asterisk log mappings"),
360 };
361
362 static int load_module(void)
363 {
364         ast_debug(3, "Starting PJPROJECT logging to Asterisk logger\n");
365
366         if (!(pjproject_sorcery = ast_sorcery_open())) {
367                 ast_log(LOG_ERROR, "Failed to open SIP sorcery failed to open\n");
368                 return AST_MODULE_LOAD_DECLINE;
369         }
370
371         ast_sorcery_apply_default(pjproject_sorcery, "log_mappings", "config", "pjproject.conf,criteria=type=log_mappings");
372         if (ast_sorcery_object_register(pjproject_sorcery, "log_mappings", mapping_alloc, NULL, NULL)) {
373                 ast_log(LOG_WARNING, "Failed to register pjproject log_mappings object with sorcery\n");
374                 ast_sorcery_unref(pjproject_sorcery);
375                 pjproject_sorcery = NULL;
376                 return AST_MODULE_LOAD_DECLINE;
377         }
378
379         ast_sorcery_object_field_register(pjproject_sorcery, "log_mappings", "type", "", OPT_NOOP_T, 0, 0);
380         ast_sorcery_object_field_register(pjproject_sorcery, "log_mappings", "asterisk_debug", "", OPT_STRINGFIELD_T, 0, STRFLDSET(struct log_mappings, asterisk_debug));
381         ast_sorcery_object_field_register(pjproject_sorcery, "log_mappings", "asterisk_error", "",  OPT_STRINGFIELD_T, 0, STRFLDSET(struct log_mappings, asterisk_error));
382         ast_sorcery_object_field_register(pjproject_sorcery, "log_mappings", "asterisk_warning", "",  OPT_STRINGFIELD_T, 0, STRFLDSET(struct log_mappings, asterisk_warning));
383         ast_sorcery_object_field_register(pjproject_sorcery, "log_mappings", "asterisk_notice", "",  OPT_STRINGFIELD_T, 0, STRFLDSET(struct log_mappings, asterisk_notice));
384         ast_sorcery_object_field_register(pjproject_sorcery, "log_mappings", "asterisk_verbose", "",  OPT_STRINGFIELD_T, 0, STRFLDSET(struct log_mappings, asterisk_verbose));
385
386         default_log_mappings = ast_sorcery_alloc(pjproject_sorcery, "log_mappings", "log_mappings");
387         if (!default_log_mappings) {
388                 ast_log(LOG_ERROR, "Unable to allocate memory for pjproject log_mappings\n");
389                 return AST_MODULE_LOAD_DECLINE;
390         }
391         ast_string_field_set(default_log_mappings, asterisk_error, "0,1");
392         ast_string_field_set(default_log_mappings, asterisk_warning, "2");
393         ast_string_field_set(default_log_mappings, asterisk_debug, "3,4,5");
394
395         ast_sorcery_load(pjproject_sorcery);
396
397         pj_init();
398
399         decor_orig = pj_log_get_decor();
400         log_cb_orig = pj_log_get_log_func();
401
402         if (AST_VECTOR_INIT(&buildopts, 64)) {
403                 return AST_MODULE_LOAD_DECLINE;
404         }
405
406         /*
407          * On startup, we want to capture the dump once and store it.
408          */
409         pj_log_set_log_func(capture_buildopts_cb);
410         pj_log_set_decor(0);
411         pj_dump_config();
412         pj_log_set_decor(PJ_LOG_HAS_SENDER | PJ_LOG_HAS_INDENT);
413         pj_log_set_log_func(log_forwarder);
414
415         ast_cli_register_multiple(pjproject_cli, ARRAY_LEN(pjproject_cli));
416
417         return AST_MODULE_LOAD_SUCCESS;
418 }
419
420 #define NOT_EQUALS(a, b) (a != b)
421
422 static int unload_module(void)
423 {
424         ast_cli_unregister_multiple(pjproject_cli, ARRAY_LEN(pjproject_cli));
425         pj_log_set_log_func(log_cb_orig);
426         pj_log_set_decor(decor_orig);
427
428         AST_VECTOR_REMOVE_CMP_UNORDERED(&buildopts, NULL, NOT_EQUALS, ast_free);
429         AST_VECTOR_FREE(&buildopts);
430
431         ast_debug(3, "Stopped PJPROJECT logging to Asterisk logger\n");
432
433         pj_shutdown();
434
435         ao2_cleanup(default_log_mappings);
436         default_log_mappings = NULL;
437
438         ast_sorcery_unref(pjproject_sorcery);
439
440         return 0;
441 }
442
443 static int reload_module(void)
444 {
445         if (pjproject_sorcery) {
446                 ast_sorcery_reload(pjproject_sorcery);
447         }
448
449         return AST_MODULE_LOAD_SUCCESS;
450 }
451
452 AST_MODULE_INFO(ASTERISK_GPL_KEY, AST_MODFLAG_GLOBAL_SYMBOLS | AST_MODFLAG_LOAD_ORDER, "PJPROJECT Log and Utility Support",
453         .support_level = AST_MODULE_SUPPORT_CORE,
454         .load = load_module,
455         .unload = unload_module,
456         .reload = reload_module,
457         .load_pri = AST_MODPRI_CHANNEL_DEPEND - 6,
458 );