<!-- Kamailio Pull Request Template -->
<!-- IMPORTANT: - for detailed contributing guidelines, read: https://github.com/kamailio/kamailio/blob/master/.github/CONTRIBUTING.md - pull requests must be done to master branch, unless they are backports of fixes from master branch to a stable branch - backports to stable branches must be done with 'git cherry-pick -x ...' - code is contributed under BSD for core and main components (tm, sl, auth, tls) - code is contributed GPLv2 or a compatible license for the other components - GPL code is contributed with OpenSSL licensing exception -->
#### Pre-Submission Checklist <!-- Go over all points below, and after creating the PR, tick all the checkboxes that apply --> <!-- All points should be verified, otherwise, read the CONTRIBUTING guidelines from above--> <!-- If you're unsure about any of these, don't hesitate to ask on sr-dev mailing list --> - [x] Commit message has the format required by CONTRIBUTING guide - [x] Commits are split per component (core, individual modules, libs, utils, ...) - [x] Each component has a single commit (if not, squash them into one commit) - [x] No commits to README files for modules (changes must be done to docbook files in `doc/` subfolder, the README file is autogenerated)
#### Type Of Change - [ ] Small bug fix (non-breaking change which fixes an issue) - [x] New feature (non-breaking change which adds new functionality) - [ ] Breaking change (fix or feature that would change existing functionality)
#### Checklist: <!-- Go over all points below, and after creating the PR, tick the checkboxes that apply --> - [ ] PR should be backported to stable branches - [x] Tested changes locally - [ ] Related to issue #XXXX (replace XXXX with an open issue number)
#### Description
Allow Kamailio modules to register their log function so that all Kamailio log messages (coming from core and other modules) are logged uniformly in the format defined by the custom log function.
To enable the custom log format feature, Kamailio must be compiled with the `CUSTOM_LOG_FMT` flag. Then the module that wishes to modify the log format has to call `km_custom_log_func_set` during the initialization to supply a custom log formatting function (see `km_default_custom_log_func` as an example).
You can view, comment on, or merge this pull request online at:
https://github.com/kamailio/kamailio/pull/3902
-- Commit Summary --
* core: add support for custom log function
-- File Changes --
M src/core/dprint.c (19) M src/core/dprint.h (47)
-- Patch Links --
https://github.com/kamailio/kamailio/pull/3902.patch https://github.com/kamailio/kamailio/pull/3902.diff
@anmartan pushed 1 commit.
52277d9b74e6ba2973ecaa0163a49be54bdd5454 core: add support for custom log function
Any reason that:
``` ksr_logdata_t __kld = {0}; ```
I replaced with:
``` ksr_logdata_t __kld = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0}; ```
Also, `asprintf()` allocates memory, it is freed somewhere?
Then, when this new mechanism is used and what is the benefit? Can you provide some examples?
@anmartan pushed 1 commit.
2ecd44410be96c441f137a0c02ffe47a51f20fd9 --amend
Any reason that:
ksr_logdata_t __kld = {0};I replaced with:
ksr_logdata_t __kld = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0};
I've reverted the change.
Also, `asprintf()` allocates memory, it is freed somewhere?
It is now, at the end of the function.
Hi @miconda ,
thanks for your feedback!
Regarding `ksr_logdata_t`, most likely it got flagged by some static checker, but we've re-tested the original version and couldn't pin-point which exact check/rule triggered this.
Regarding the `asprintf` - thanks for spotting the memory leak! We've never detected it using our memory checkers since we never actually use the default stub continuously - it always gets replaces when our custom module is initialised.
Then, when this new mechanism is used and what is the benefit? Can you provide some examples?
The benefits of being able to control the output format of the logs are mainly evident when Kamailio is used in a deployment alongside other products/tools, all of which are generating their logs using a common scheme. Thus, being able to control Kamailio log output scheme helps to: 1. keep the log collection/processing pipeline manageable (since all logs flowing through it share a common scheme) 2. reduce the developer cognitive load from having to switch to different log formats during development stage (not dealing with production logs from log pipeline but with direct Kamailio output)
Here's a sample output made possible with the help of this patch: (scheme used: `<pname> <ver> <timestamp> <lvl> <mname> <pid>:<file>:<line> <msg>`) ``` pname 1.35.15 2024-06-20T10:43:24.134886Z WARNING pname 13:libpname/core.cpp:85 Core successfully created! pname 1.35.15 2024-06-20T10:43:24.135058Z INFO tls 13:tls_mod.c:445 use OpenSSL version: 30000070 pname 1.35.15 2024-06-20T10:43:24.135079Z INFO tls 13:tls_mod.c:447 With ECDH-Support! pname 1.35.15 2024-06-20T10:43:24.135096Z INFO tls 13:tls_mod.c:450 With Diffie Hellman pname 1.35.15 2024-06-20T10:43:24.135166Z WARNING tls 13:tls_init.c:980 openssl bug #1491 (crash/mem leaks on low memory) workaround enabled (on low memory tls operations will fail preemptively) with free memory thresholds 11534336 and 5767168 bytes pname 1.35.15 2024-06-20T10:43:24.135203Z INFO core 13:core/cfg/cfg_ctx.c:589 tls.low_mem_threshold1 has been changed to 11534336 pname 1.35.15 2024-06-20T10:43:24.135223Z INFO core 13:core/cfg/cfg_ctx.c:589 tls.low_mem_threshold2 has been changed to 5767168 ... pname 1.35.15 2024-06-20T10:43:24.136142Z INFO tls 13:tls_mod.c:491 Loading SSL_CTX in process_no=0 rank=-127 ksr_tls_threads_mode=0 pname 1.35.15 2024-06-20T10:43:24.136176Z INFO tls 13:tls_domain.c:353 TLSs<default>: tls_method=23 pname 1.35.15 2024-06-20T10:43:24.136200Z INFO tls 13:tls_domain.c:365 TLSs<default>: certificate='/usr/local/lib/pname/certs/serv.crt' ... pname 1.35.15 2024-06-20T10:43:33.612026Z TRACE pname 16:libpname/log/trace_object.hpp:19 Create > binding::SipMsg() pname 1.35.15 2024-06-20T10:43:33.612093Z TRACE pname 16:libpname/binding/sip_msg.cpp:645 Call > binding::SipMsg::getCallId() pname 1.35.15 2024-06-20T10:43:33.612136Z TRACE pname 16:libpname/log/logger.cpp:100 Call > zroute::Logger::setTraceId("3811ef5eb36d7024f1f3e7bfaf70e572") pname 1.35.15 2024-06-20T10:43:33.612194Z INFO pname 16:/usr/local/etc/pname/./route.cfg:11 TraceID[3811ef5eb36d7024f1f3e7bfaf70e572] Processing "INVITE" request received from "sip:10.22.10.9:5060" [Call-Id: "8t1b49///1-94@10.22.10.9"] pname 1.35.15 2024-06-20T10:43:33.612218Z INFO debugger 16:debugger_api.c:351 TraceID[3811ef5eb36d7024f1f3e7bfaf70e572] request_route=[DEFAULT_ROUTE] c=[/usr/local/etc/pname/./route.cfg] l=12 a=25 n=MYLOG_DBG pname 1.35.15 2024-06-20T10:43:33.612244Z TRACE pname 16:libpname/log/logger.cpp:110 TraceID[3811ef5eb36d7024f1f3e7bfaf70e572] Call > zroute::Logger::isTraceIdSet() pname 1.35.15 2024-06-20T10:43:33.613788Z DEBUG pname 16:/usr/local/etc/pname/././invite.cfg:2 TraceID[3811ef5eb36d7024f1f3e7bfaf70e572] Received INVITE request, routing pname 1.35.15 2024-06-20T10:43:33.612266Z DEBUG pname 16:/usr/local/etc/pname/./route.cfg:12 TraceID[3811ef5eb36d7024f1f3e7bfaf70e572] INVITE sip:test@example.com SIP/2.0 ```
Hi @miconda, is there anything else that needs clarifying?
I had no time for a proper review, it seems rather important change considering that logging is critical component. Does it affect in any way the modules `log_custom` or `log_systemd`?
Maybe other can review as well and make remarks on this change.
Does it affect in any way the modules log_custom or log_systemd?
It does not. Mentioned modules rely on the `_km_log_func` (set via `km_log_func_set`) while this patch uses `_km_custom_log_func` (set via `km_custom_log_func_set`) and makes no changes to the `_km_log_func`. The only downside is that if the feature from this patch is enabled using the `CUSTOM_LOG_FMT`, then default log macros will bypass `_km_log_func` and will use `_km_custom_log_func` instead. In short - mentioned modules are currently not compatible with this patch.
This PR is stale because it has been open 6 weeks with no activity. Remove stale label or comment or this will be closed in 2 weeks.
Does it affect in any way the modules log_custom or log_systemd?
Hi @miconda , did the above answer provide sufficient details for you?
it seems rather important change considering that logging is critical component
Perhaps you would us to make any additional changes to further isolate this feature to reduce the chance of misuse or unintended performance degradation?
I will look into it in more details soon, summer holidays kept me out of the office quite a lot. It would be good to find a way to have a single framework that works for all logging related modules, like `log_custom` or `log_systemd` (maybe these modules can be adapted to the way proposed by this patch, if it offers more flexibility that the existing one).
I got a bit of the time to look deeper at it and seems to be a mechanism similar to structured logging, which is already used for JSON logging engine. See:
- https://github.com/kamailio/kamailio/blob/master/src/core/dprint.h#L338-L353
I added a function to be able to set custom slog callback from anywhere with the commit c5c84099fc29623c4f0b8faf9e6151eeaf4421c1 . Before was only done from core based on cli parameter.
With the slog function you get the attributes in a single structure parameter, while this PR adds a similar approach, but with attributes given as function parameters. If I haven't missed something from this PR, you have now all it is needed without merging this PR.
@miconda thanks for looking into this! Indeed it seems that structured logging takes care of most of our needs. But I'm not sure whether it would allow us to do uniform logging from config files. Let me explain: right now we're using custom log function from the PR and we're "manually" resolving `$cfg(file)`/`$cfg(line)` PVEs and feeding them into the log handler. I haven't seen such functionality in `dprint.c/.h` nor there seems to exist a version of `LOG_XX` macro that would allow to inject that data.
I suppose we could completely bypass `LOG_XX` macros and call the `_ksr_slog_func` function manually by passing it manually constructed `ksr_logdata_t` structure, although that could lead to some hard to catch bugs if the logger type is ever changed. How feasible is it to create another version of `LOG_XX` (for example `LOG_SD`, short for "source data") that takes source file and line number as arguments?
Source file and line number are part of the structure passed to the slog-function:
- https://github.com/kamailio/kamailio/blob/master/src/core/dprint.h#L348-L349
You can ignore the other fields if you don't need the corresponding attributes.
Source file and line number are part of the structure passed to the slog-function:
I understand, my question was about the possibility of adding a flavour of the `LOG_XX` macro that takes file/line as arguments and populates the slog structure rather than always using `__FILE__`/`__LINE__`. One example for such use-case would be custom config logging commands that extract executed config file's name/line from PVEs and pass the to the new `LOG_XX` macro for the nearly identical logging behaviour regardless of whether logs are generated from CFG or C code.
You can call `_ksr_slog_func(...)` function directly, with the `ksr_logdata_t` structure filled as you want.
With this PR, I understood you actually want to replace the default `_ksr_slog_func(...)` with your own implementation from a module, so I added the option to be able to set the `_ksr_slog_func`.
With this PR, I understood you actually want to replace the default _ksr_slog_func(...)
That is right.
so I added the option to be able to set the _ksr_slog_func.
Thanks!
I'll try to submit another PR with improvements to the `LOG_XX` macro as mentioned above for a uniform logging entry point.
OK, closing. A new PR can be created with other changes.
Closed #3902.
-
Daniel-Constantin Mierla -
github-actions[bot]
-
Ivan Ribakov
-
Nirv.Ana