pjproject: Add cache_pools debugging option.
[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="startup">
45                                 <synopsis>Asterisk startup time options for PJPROJECT</synopsis>
46                                 <description>
47                                         <note><para>The id of this object, as well as its type, must be
48                                         'startup' or it won't be found.</para></note>
49                                 </description>
50                                 <configOption name="type">
51                                         <synopsis>Must be of type 'startup'.</synopsis>
52                                 </configOption>
53                                 <configOption name="log_level" default="2">
54                                         <synopsis>Initial maximum pjproject logging level to log.</synopsis>
55                                         <description>
56                                                 <para>Valid values are: 0-6, and default</para>
57                                         <note><para>
58                                                 This option is needed very early in the startup process
59                                                 so it can only be read from config files because the
60                                                 modules for other methods have not been loaded yet.
61                                         </para></note>
62                                         </description>
63                                 </configOption>
64                         </configObject>
65                         <configObject name="log_mappings">
66                                 <synopsis>PJPROJECT to Asterisk Log Level Mapping</synopsis>
67                                 <description><para>Warnings and errors in the pjproject libraries are generally handled
68                                         by Asterisk.  In many cases, Asterisk wouldn't even consider them to
69                                         be warnings or errors so the messages emitted by pjproject directly
70                                         are either superfluous or misleading.  The 'log_mappings'
71                                         object allows mapping the pjproject levels to Asterisk levels, or nothing.
72                                         </para>
73                                         <note><para>The id of this object, as well as its type, must be
74                                         'log_mappings' or it won't be found.</para></note>
75                                 </description>
76                                 <configOption name="type">
77                                         <synopsis>Must be of type 'log_mappings'.</synopsis>
78                                 </configOption>
79                                 <configOption name="asterisk_error" default="0,1">
80                                         <synopsis>A comma separated list of pjproject log levels to map to Asterisk LOG_ERROR.</synopsis>
81                                 </configOption>
82                                 <configOption name="asterisk_warning" default="2">
83                                         <synopsis>A comma separated list of pjproject log levels to map to Asterisk LOG_WARNING.</synopsis>
84                                 </configOption>
85                                 <configOption name="asterisk_notice" default="">
86                                         <synopsis>A comma separated list of pjproject log levels to map to Asterisk LOG_NOTICE.</synopsis>
87                                 </configOption>
88                                 <configOption name="asterisk_debug" default="3,4,5,6">
89                                         <synopsis>A comma separated list of pjproject log levels to map to Asterisk LOG_DEBUG.</synopsis>
90                                 </configOption>
91                                 <configOption name="asterisk_verbose" default="">
92                                         <synopsis>A comma separated list of pjproject log levels to map to Asterisk LOG_VERBOSE.</synopsis>
93                                 </configOption>
94                         </configObject>
95                 </configFile>
96         </configInfo>
97  ***/
98
99 #include "asterisk.h"
100
101 #include <stdarg.h>
102 #include <pjlib.h>
103 #include <pjsip.h>
104 #include <pj/log.h>
105
106 #include "asterisk/options.h"
107 #include "asterisk/logger.h"
108 #include "asterisk/module.h"
109 #include "asterisk/cli.h"
110 #include "asterisk/res_pjproject.h"
111 #include "asterisk/vector.h"
112 #include "asterisk/sorcery.h"
113
114 static struct ast_sorcery *pjproject_sorcery;
115 static pj_log_func *log_cb_orig;
116 static unsigned decor_orig;
117
118 static AST_VECTOR(buildopts, char *) buildopts;
119
120 /*! Protection from other log intercept instances.  There can be only one at a time. */
121 AST_MUTEX_DEFINE_STATIC(pjproject_log_intercept_lock);
122
123 struct pjproject_log_intercept_data {
124         pthread_t thread;
125         int fd;
126 };
127
128 static struct pjproject_log_intercept_data pjproject_log_intercept = {
129         .thread = AST_PTHREADT_NULL,
130         .fd = -1,
131 };
132
133 struct log_mappings {
134         /*! Sorcery object details */
135         SORCERY_OBJECT(details);
136         /*! These are all comma-separated lists of pjproject log levels */
137         AST_DECLARE_STRING_FIELDS(
138                 /*! pjproject log levels mapped to Asterisk ERROR */
139                 AST_STRING_FIELD(asterisk_error);
140                 /*! pjproject log levels mapped to Asterisk WARNING */
141                 AST_STRING_FIELD(asterisk_warning);
142                 /*! pjproject log levels mapped to Asterisk NOTICE */
143                 AST_STRING_FIELD(asterisk_notice);
144                 /*! pjproject log levels mapped to Asterisk VERBOSE */
145                 AST_STRING_FIELD(asterisk_verbose);
146                 /*! pjproject log levels mapped to Asterisk DEBUG */
147                 AST_STRING_FIELD(asterisk_debug);
148         );
149 };
150
151 static struct log_mappings *default_log_mappings;
152
153 static struct log_mappings *get_log_mappings(void)
154 {
155         struct log_mappings *mappings;
156
157         mappings = ast_sorcery_retrieve_by_id(pjproject_sorcery, "log_mappings", "log_mappings");
158         if (!mappings) {
159                 return ao2_bump(default_log_mappings);
160         }
161
162         return mappings;
163 }
164
165 #define __LOG_SUPPRESS -1
166
167 static int get_log_level(int pj_level)
168 {
169         int mapped_level;
170         unsigned char l;
171         struct log_mappings *mappings;
172
173         mappings = get_log_mappings();
174         if (!mappings) {
175                 return __LOG_ERROR;
176         }
177
178         l = '0' + fmin(pj_level, 9);
179
180         if (strchr(mappings->asterisk_error, l)) {
181                 mapped_level = __LOG_ERROR;
182         } else if (strchr(mappings->asterisk_warning, l)) {
183                 mapped_level = __LOG_WARNING;
184         } else if (strchr(mappings->asterisk_notice, l)) {
185                 mapped_level = __LOG_NOTICE;
186         } else if (strchr(mappings->asterisk_verbose, l)) {
187                 mapped_level = __LOG_VERBOSE;
188         } else if (strchr(mappings->asterisk_debug, l)) {
189                 mapped_level = __LOG_DEBUG;
190         } else {
191                 mapped_level = __LOG_SUPPRESS;
192         }
193
194         ao2_ref(mappings, -1);
195         return mapped_level;
196 }
197
198 static void log_forwarder(int level, const char *data, int len)
199 {
200         int ast_level;
201         /* PJPROJECT doesn't provide much in the way of source info */
202         const char * log_source = "pjproject";
203         int log_line = 0;
204         const char *log_func = "<?>";
205
206         if (pjproject_log_intercept.fd != -1
207                 && pjproject_log_intercept.thread == pthread_self()) {
208                 /*
209                  * We are handling a CLI command intercepting PJPROJECT
210                  * log output.
211                  */
212                 ast_cli(pjproject_log_intercept.fd, "%s\n", data);
213                 return;
214         }
215
216         ast_level = get_log_level(level);
217
218         if (ast_level == __LOG_SUPPRESS) {
219                 return;
220         }
221
222         /* PJPROJECT uses indention to indicate function call depth. We'll prepend
223          * log statements with a tab so they'll have a better shot at lining
224          * up */
225         ast_log(ast_level, log_source, log_line, log_func, "\t%s\n", data);
226 }
227
228 static void capture_buildopts_cb(int level, const char *data, int len)
229 {
230         char *dup;
231
232         if (strstr(data, "Teluu") || strstr(data, "Dumping")) {
233                 return;
234         }
235
236         dup = ast_strdup(ast_skip_blanks(data));
237         if (dup && AST_VECTOR_ADD_SORTED(&buildopts, dup, strcmp)) {
238                 ast_free(dup);
239         }
240 }
241
242 #pragma GCC diagnostic ignored "-Wformat-nonliteral"
243 int ast_pjproject_get_buildopt(char *option, char *format_string, ...)
244 {
245         int res = 0;
246         char *format_temp;
247         int i;
248
249         format_temp = ast_alloca(strlen(option) + strlen(" : ") + strlen(format_string) + 1);
250         sprintf(format_temp, "%s : %s", option, format_string);
251
252         for (i = 0; i < AST_VECTOR_SIZE(&buildopts); i++) {
253                 va_list arg_ptr;
254                 va_start(arg_ptr, format_string);
255                 res = vsscanf(AST_VECTOR_GET(&buildopts, i), format_temp, arg_ptr);
256                 va_end(arg_ptr);
257                 if (res) {
258                         break;
259                 }
260         }
261
262         return res;
263 }
264 #pragma GCC diagnostic warning "-Wformat-nonliteral"
265
266 void ast_pjproject_log_intercept_begin(int fd)
267 {
268         /* Protect from other CLI instances trying to do this at the same time. */
269         ast_mutex_lock(&pjproject_log_intercept_lock);
270
271         pjproject_log_intercept.thread = pthread_self();
272         pjproject_log_intercept.fd = fd;
273 }
274
275 void ast_pjproject_log_intercept_end(void)
276 {
277         pjproject_log_intercept.fd = -1;
278         pjproject_log_intercept.thread = AST_PTHREADT_NULL;
279
280         ast_mutex_unlock(&pjproject_log_intercept_lock);
281 }
282
283 static char *handle_pjproject_show_buildopts(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
284 {
285         int i;
286
287         switch (cmd) {
288         case CLI_INIT:
289                 e->command = "pjproject show buildopts";
290                 e->usage =
291                         "Usage: pjproject show buildopts\n"
292                         "       Show the compile time config of the pjproject that Asterisk is\n"
293                         "       running against.\n";
294                 return NULL;
295         case CLI_GENERATE:
296                 return NULL;
297         }
298
299         ast_cli(a->fd, "PJPROJECT compile time config currently running against:\n");
300
301         for (i = 0; i < AST_VECTOR_SIZE(&buildopts); i++) {
302                 ast_cli(a->fd, "%s\n", AST_VECTOR_GET(&buildopts, i));
303         }
304
305         return CLI_SUCCESS;
306 }
307
308 static void mapping_destroy(void *object)
309 {
310         struct log_mappings *mappings = object;
311
312         ast_string_field_free_memory(mappings);
313 }
314
315 static void *mapping_alloc(const char *name)
316 {
317         struct log_mappings *mappings = ast_sorcery_generic_alloc(sizeof(*mappings), mapping_destroy);
318         if (!mappings) {
319                 return NULL;
320         }
321         ast_string_field_init(mappings, 128);
322
323         return mappings;
324 }
325
326 static char *handle_pjproject_show_log_mappings(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
327 {
328         struct ast_variable *objset;
329         struct ast_variable *i;
330         struct log_mappings *mappings;
331
332         switch (cmd) {
333         case CLI_INIT:
334                 e->command = "pjproject show log mappings";
335                 e->usage =
336                         "Usage: pjproject show log mappings\n"
337                         "       Show pjproject to Asterisk log mappings\n";
338                 return NULL;
339         case CLI_GENERATE:
340                 return NULL;
341         }
342
343         ast_cli(a->fd, "PJPROJECT to Asterisk log mappings:\n");
344         ast_cli(a->fd, "Asterisk Level   : PJPROJECT log levels\n");
345
346         mappings = get_log_mappings();
347         if (!mappings) {
348                 ast_log(LOG_ERROR, "Unable to retrieve pjproject log_mappings\n");
349                 return CLI_SUCCESS;
350         }
351
352         objset = ast_sorcery_objectset_create(pjproject_sorcery, mappings);
353         if (!objset) {
354                 ao2_ref(mappings, -1);
355                 return CLI_SUCCESS;
356         }
357
358         for (i = objset; i; i = i->next) {
359                 ast_cli(a->fd, "%-16s : %s\n", i->name, i->value);
360         }
361         ast_variables_destroy(objset);
362
363         ao2_ref(mappings, -1);
364         return CLI_SUCCESS;
365 }
366
367 struct max_pjproject_log_level_check {
368         /*!
369          * Compile time sanity check to determine if
370          * MAX_PJ_LOG_MAX_LEVEL matches CLI syntax.
371          */
372         char check[1 / (6 == MAX_PJ_LOG_MAX_LEVEL)];
373 };
374
375 static char *handle_pjproject_set_log_level(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
376 {
377         int level_new;
378         int level_old;
379
380         switch (cmd) {
381         case CLI_INIT:
382                 e->command = "pjproject set log level {default|0|1|2|3|4|5|6}";
383                 e->usage =
384                         "Usage: pjproject set log level {default|<level>}\n"
385                         "\n"
386                         "       Set the maximum active pjproject logging level.\n"
387                         "       See pjproject.conf.sample for additional information\n"
388                         "       about the various levels pjproject uses.\n";
389                 return NULL;
390         case CLI_GENERATE:
391                 return NULL;
392         }
393
394         if (a->argc != 5) {
395                 return CLI_SHOWUSAGE;
396         }
397
398         if (!strcasecmp(a->argv[4], "default")) {
399                 level_new = DEFAULT_PJ_LOG_MAX_LEVEL;
400         } else {
401                 if (sscanf(a->argv[4], "%30d", &level_new) != 1
402                         || level_new < 0 || MAX_PJ_LOG_MAX_LEVEL < level_new) {
403                         return CLI_SHOWUSAGE;
404                 }
405         }
406
407         /* Update pjproject logging level */
408         if (ast_pjproject_max_log_level < level_new) {
409                 level_new = ast_pjproject_max_log_level;
410                 ast_cli(a->fd,
411                         "Asterisk built or linked with pjproject PJ_LOG_MAX_LEVEL=%d.\n"
412                         "Lowering request to the max supported level.\n",
413                         ast_pjproject_max_log_level);
414         }
415         level_old = ast_option_pjproject_log_level;
416         if (level_old == level_new) {
417                 ast_cli(a->fd, "pjproject log level is still %d.\n", level_old);
418         } else {
419                 ast_cli(a->fd, "pjproject log level was %d and is now %d.\n",
420                         level_old, level_new);
421                 ast_option_pjproject_log_level = level_new;
422                 pj_log_set_level(level_new);
423         }
424
425         return CLI_SUCCESS;
426 }
427
428 static char *handle_pjproject_show_log_level(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
429 {
430         switch (cmd) {
431         case CLI_INIT:
432                 e->command = "pjproject show log level";
433                 e->usage =
434                         "Usage: pjproject show log level\n"
435                         "\n"
436                         "       Show the current maximum active pjproject logging level.\n"
437                         "       See pjproject.conf.sample for additional information\n"
438                         "       about the various levels pjproject uses.\n";
439                 return NULL;
440         case CLI_GENERATE:
441                 return NULL;
442         }
443
444         if (a->argc != 4) {
445                 return CLI_SHOWUSAGE;
446         }
447
448         ast_cli(a->fd, "pjproject log level is %d.%s\n",
449                 ast_option_pjproject_log_level,
450                 ast_option_pjproject_log_level == DEFAULT_PJ_LOG_MAX_LEVEL ? " (default)" : "");
451
452         return CLI_SUCCESS;
453 }
454
455 static struct ast_cli_entry pjproject_cli[] = {
456         AST_CLI_DEFINE(handle_pjproject_set_log_level, "Set the maximum active pjproject logging level"),
457         AST_CLI_DEFINE(handle_pjproject_show_buildopts, "Show the compiled config of the pjproject in use"),
458         AST_CLI_DEFINE(handle_pjproject_show_log_mappings, "Show pjproject to Asterisk log mappings"),
459         AST_CLI_DEFINE(handle_pjproject_show_log_level, "Show the maximum active pjproject logging level"),
460 };
461
462 void ast_pjproject_caching_pool_init(pj_caching_pool *cp,
463         const pj_pool_factory_policy *policy, pj_size_t max_capacity)
464 {
465         /* Passing a max_capacity of zero disables caching pools */
466         pj_caching_pool_init(cp, policy, ast_option_pjproject_cache_pools ? max_capacity : 0);
467 }
468
469 void ast_pjproject_caching_pool_destroy(pj_caching_pool *cp)
470 {
471         pj_caching_pool_destroy(cp);
472 }
473
474 static int load_module(void)
475 {
476         ast_debug(3, "Starting PJPROJECT logging to Asterisk logger\n");
477
478         if (!(pjproject_sorcery = ast_sorcery_open())) {
479                 ast_log(LOG_ERROR, "Failed to open SIP sorcery failed to open\n");
480                 return AST_MODULE_LOAD_DECLINE;
481         }
482
483         ast_sorcery_apply_default(pjproject_sorcery, "log_mappings", "config", "pjproject.conf,criteria=type=log_mappings");
484         if (ast_sorcery_object_register(pjproject_sorcery, "log_mappings", mapping_alloc, NULL, NULL)) {
485                 ast_log(LOG_WARNING, "Failed to register pjproject log_mappings object with sorcery\n");
486                 ast_sorcery_unref(pjproject_sorcery);
487                 pjproject_sorcery = NULL;
488                 return AST_MODULE_LOAD_DECLINE;
489         }
490
491         ast_sorcery_object_field_register(pjproject_sorcery, "log_mappings", "type", "", OPT_NOOP_T, 0, 0);
492         ast_sorcery_object_field_register(pjproject_sorcery, "log_mappings", "asterisk_debug", "", OPT_STRINGFIELD_T, 0, STRFLDSET(struct log_mappings, asterisk_debug));
493         ast_sorcery_object_field_register(pjproject_sorcery, "log_mappings", "asterisk_error", "",  OPT_STRINGFIELD_T, 0, STRFLDSET(struct log_mappings, asterisk_error));
494         ast_sorcery_object_field_register(pjproject_sorcery, "log_mappings", "asterisk_warning", "",  OPT_STRINGFIELD_T, 0, STRFLDSET(struct log_mappings, asterisk_warning));
495         ast_sorcery_object_field_register(pjproject_sorcery, "log_mappings", "asterisk_notice", "",  OPT_STRINGFIELD_T, 0, STRFLDSET(struct log_mappings, asterisk_notice));
496         ast_sorcery_object_field_register(pjproject_sorcery, "log_mappings", "asterisk_verbose", "",  OPT_STRINGFIELD_T, 0, STRFLDSET(struct log_mappings, asterisk_verbose));
497
498         default_log_mappings = ast_sorcery_alloc(pjproject_sorcery, "log_mappings", "log_mappings");
499         if (!default_log_mappings) {
500                 ast_log(LOG_ERROR, "Unable to allocate memory for pjproject log_mappings\n");
501                 return AST_MODULE_LOAD_DECLINE;
502         }
503         ast_string_field_set(default_log_mappings, asterisk_error, "0,1");
504         ast_string_field_set(default_log_mappings, asterisk_warning, "2");
505         ast_string_field_set(default_log_mappings, asterisk_debug, "3,4,5,6");
506
507         ast_sorcery_load(pjproject_sorcery);
508
509         AST_PJPROJECT_INIT_LOG_LEVEL();
510         pj_init();
511
512         decor_orig = pj_log_get_decor();
513         log_cb_orig = pj_log_get_log_func();
514
515         if (AST_VECTOR_INIT(&buildopts, 64)) {
516                 return AST_MODULE_LOAD_DECLINE;
517         }
518
519         /*
520          * On startup, we want to capture the dump once and store it.
521          */
522         pj_log_set_log_func(capture_buildopts_cb);
523         pj_log_set_decor(0);
524         pj_log_set_level(MAX_PJ_LOG_MAX_LEVEL);/* Set level to guarantee the dump output. */
525         pj_dump_config();
526         pj_log_set_decor(PJ_LOG_HAS_SENDER | PJ_LOG_HAS_INDENT);
527         pj_log_set_log_func(log_forwarder);
528         if (ast_pjproject_max_log_level < ast_option_pjproject_log_level) {
529                 ast_log(LOG_WARNING,
530                         "Asterisk built or linked with pjproject PJ_LOG_MAX_LEVEL=%d which is too low for startup level: %d.\n",
531                         ast_pjproject_max_log_level, ast_option_pjproject_log_level);
532                 ast_option_pjproject_log_level = ast_pjproject_max_log_level;
533         }
534         pj_log_set_level(ast_option_pjproject_log_level);
535         if (!AST_VECTOR_SIZE(&buildopts)) {
536                 ast_log(LOG_NOTICE,
537                         "Asterisk built or linked with pjproject PJ_LOG_MAX_LEVEL=%d which is too low to get buildopts.\n",
538                         ast_pjproject_max_log_level);
539         }
540
541         ast_cli_register_multiple(pjproject_cli, ARRAY_LEN(pjproject_cli));
542
543         return AST_MODULE_LOAD_SUCCESS;
544 }
545
546 #define NOT_EQUALS(a, b) (a != b)
547
548 static int unload_module(void)
549 {
550         ast_cli_unregister_multiple(pjproject_cli, ARRAY_LEN(pjproject_cli));
551         pj_log_set_log_func(log_cb_orig);
552         pj_log_set_decor(decor_orig);
553
554         AST_VECTOR_CALLBACK_VOID(&buildopts, ast_free);
555         AST_VECTOR_FREE(&buildopts);
556
557         ast_debug(3, "Stopped PJPROJECT logging to Asterisk logger\n");
558
559         pj_shutdown();
560
561         ao2_cleanup(default_log_mappings);
562         default_log_mappings = NULL;
563
564         ast_sorcery_unref(pjproject_sorcery);
565
566         return 0;
567 }
568
569 static int reload_module(void)
570 {
571         if (pjproject_sorcery) {
572                 ast_sorcery_reload(pjproject_sorcery);
573         }
574
575         return AST_MODULE_LOAD_SUCCESS;
576 }
577
578 AST_MODULE_INFO(ASTERISK_GPL_KEY, AST_MODFLAG_GLOBAL_SYMBOLS | AST_MODFLAG_LOAD_ORDER, "PJPROJECT Log and Utility Support",
579         .support_level = AST_MODULE_SUPPORT_CORE,
580         .load = load_module,
581         .unload = unload_module,
582         .reload = reload_module,
583         .load_pri = AST_MODPRI_CHANNEL_DEPEND - 6,
584 );