[kamailio/kamailio] Unexpected log_systemd behavior when daemon is forked (#799)

List overview All Threads
Download

newer

older

git:master:9d3b3467:...

git:master:3bc5379a: pkg/docker:...

Anthony Messina

27 Sep 2016 27 Sep '16

12:57 a.m.

Starting Kamailio (4.4 with branch updates through e43d82d applied) with the following systemd unit file, native systemd/journald logging doesn't work as expected. I *do* get core logging when I use ``` log_engine_type="systemd" loadmodule "log_systemd.so" ``` but `xlog` and `sd_journal_print` *don't* send anything to the journal.

When I comment out `log_engine_type`, keeping the log_systemd.so module loaded, `sd_journal_print` *does* log the messages properly to the systemd journal, `xlog` and core startup messages are sent to syslog.

If I change the service to `Type=simple` and add the `-D` option to `ExecStart` to disable forking, then logging to systemd via `xlog` and `sd_journal_print` works, but TCP/TLS listeners aren't created.

``` [Unit] Description=Kamailio SIP Server Documentation=man:kamailio(8) http://www.kamailio.org/ After=syslog.target network-online.target Wants=network-online.target

[Service] Type=forking User=kamailio Environment=SHM_SIZE=64 Environment=PKG_SIZE=8 ExecStartPre=/usr/sbin/kamailio -c ExecStart=/usr/sbin/kamailio -m $SHM_SIZE -M $PKG_SIZE -P /run/kamailio/kamailio.pid PIDFile=/run/kamailio/kamailio.pid Restart=on-failure RestartSec=30 RuntimeDirectory=kamailio RuntimeDirectoryMode=0750

[Install] WantedBy=multi-user.target ```

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799

Attachments:

attachment.html (text/html — 3.2 KB)

Show replies by date

Daniel-Constantin Mierla

29 Sep 29 Sep

7:34 a.m.

I guess this has to do with systemd restrictions and how it daemonizes. If you don't fork in kamailio, it won't create any other worker processes, so this is not an option. Maybe you can try with -DD.

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-250392642

Anthony Messina

10:21 p.m.

I'll give -DD a shot this weekend. However, it's odd to me that child logging works when `log_engine_type="systemd"`, core logging, is not enabled, but doesn't work when core logging is enabled.

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-250608590

Daniel-Constantin Mierla

5 Oct 5 Oct

3:23 p.m.

Wondering if you had the chance to test in order to clear out this one.

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-251707326

Anthony Messina

9:55 p.m.

I just did completed some testing. Unfortunately `-DD` doesn't change the results I reported initially.

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-251811037

Daniel-Constantin Mierla

6 Oct 6 Oct

11:20 a.m.

What Type did you set for -DD?

If you start kamailio from command line with all the parameters like would be started by systemd, does it work ok?

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-251934725

Anthony Messina

11:39 a.m.

When using -DD, I tried with Type=simple since the main process was not going to fork, then Type=forking. Neither worked for me. The logging was still controlled by log_engine_type being set to systemd.

I'll try running Kamailio from the command line and see what happens there (it'll have to be tomorrow at the earliest).

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-251937969

Anthony Messina

10 Oct 10 Oct

11:30 a.m.

@miconda I get the same results as initially reported when running from the command line with -DD. If `log_engine_type="systemd"` is defined, then only core logging is available in the journal, and xlog and sd_journal_print don't send anything to the journal.

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-252593302

Daniel-Constantin Mierla

12:24 p.m.

Hmm, what do you mean by "core logging" -- messages printed from the C code of the core? The logging function is in the core and used also by xlog.

If you start from command line without any -D parameter, is all ok?

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-252603781

Anthony Messina

12:36 p.m.

Sorry, what I mean by "core logging" is http://www.kamailio.org/docs/modules/4.4.x/modules/log_systemd#idp36696668 "Core Logging."

For me, if I set `log_engine_type="systemd"`, then only kamailio startup are sent via the journal, such as the following: ``` INFO: tls [tls_init.c:403]: init_tls_compression(): tls: init_tls: disabling compression... INFO: <core> [sctp_core.c:74]: sctp_core_check_support(): SCTP API not enabled - if you want to use it, load sctp module ```

If `log_engine_type="systemd"` is set, no script-originating messages appear in the journal either via `xlog` or `sd_journal_print`.

If I load the `log_systemd` module, and do not set `log_engine_type="systemd"` , then `sd_journal_print` script messages print to the journal, but `xlog` script messages do not.

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-252606365

Daniel-Constantin Mierla

17 Sep 17 Sep

10:26 a.m.

Closed #799.

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#event-1849326770

Daniel-Constantin Mierla

10:26 a.m.

Got a bit of time to test this with latest master and it seems to work with following basic config:

``` #!KAMAILIO

####### Global Parameters #########

### LOG Levels: 3=DBG, 2=INFO, 1=NOTICE, 0=WARN, -1=ERR debug=2 log_stderror=no

memdbg=5 memlog=5

log_facility=LOG_LOCAL0 log_prefix="{$mt $hdr(CSeq) $ci} "

/* number of SIP routing processes */ children=2

log_engine_type="systemd"

####### Modules Section ########

/* set paths to location of modules */ # mpath="/usr/local/lib/kamailio/modules/"

loadmodule "log_systemd.so" loadmodule "jsonrpcs.so" loadmodule "kex.so" loadmodule "corex.so" loadmodule "tm.so" loadmodule "tmx.so" loadmodule "sl.so" loadmodule "rr.so" loadmodule "pv.so" loadmodule "maxfwd.so" loadmodule "textops.so" loadmodule "siputils.so" loadmodule "xlog.so" loadmodule "sanity.so" loadmodule "ctl.so" loadmodule "cfg_rpc.so" loadmodule "counters.so"

####### Routing Logic ########

/* Main SIP request routing logic * - processing of any incoming SIP request starts with this route * - note: this is the same as route { ... } */ request_route { xlog("===== test xlog message - R-URI is $ru\n"); sd_journal_print("LOG_ERR", "+++++ test sysd message - R-URI is $ru\n"); sl_send_reply("200", "ok"); exit; } ```

I sent test packets with sipsak, and in journalctl I see:

``` root@portugal ~ # journalctl -f -- Logs begin at Tue 2018-09-11 19:12:04 CEST. -- Sep 17 12:14:06 portugal kamailio[4540]: INFO: <core> [core/udp_server.c:205]: probe_max_receive_buffer(): SO_RCVBUF is finally 425984 Sep 17 12:14:06 portugal kamailio[4540]: INFO: <core> [core/udp_server.c:153]: probe_max_receive_buffer(): SO_RCVBUF is initially 212992 Sep 17 12:14:06 portugal kamailio[4540]: INFO: <core> [core/udp_server.c:205]: probe_max_receive_buffer(): SO_RCVBUF is finally 425984 Sep 17 12:14:06 portugal kamailio[4553]: INFO: jsonrpcs [jsonrpcs_sock.c:443]: jsonrpc_dgram_process(): a new child 0/4553 Sep 17 12:14:06 portugal kamailio[4554]: INFO: ctl [io_listener.c:214]: io_listen_loop(): io_listen_loop: using epoll_lt io watch method (config) Sep 17 12:14:48 portugal kamailio[4541]: ERROR: {1 1 OPTIONS 1446075015@127.0.1.1} <script>: ===== test xlog message - R-URI is sip:test@127.0.0.1 Sep 17 12:14:48 portugal kamailio[4541]: +++++ test sysd message - R-URI is sip:test@127.0.0.1 Sep 17 12:17:01 portugal CRON[4567]: pam_unix(cron:session): session opened for user root by (uid=0) Sep 17 12:17:01 portugal CRON[4568]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly) Sep 17 12:17:01 portugal CRON[4567]: pam_unix(cron:session): session closed for user roo Sep 17 12:20:00 portugal kamailio[4542]: ERROR: {1 1 OPTIONS 306190950@127.0.1.1} <script>: ===== test xlog message - R-URI is sip:test@127.0.0.1 Sep 17 12:20:00 portugal kamailio[4542]: +++++ test sysd message - R-URI is sip:test@127.0.0.1 ```

Kamailio was compiled and started from source tree with:

``` ./src/kamailio -f ../etc/kamailio-logsystemd.cfg -L src/modules/ -a no ```

Given that the report was made for an old version, I am going to close this issue. Test with master or 5.1 and if you still have issues, then open a new item with relevant details for the newer versions. Try to use this basic config to see if behaves differently. I tested on Debian stable.

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-421958839

Anthony Messina

11:39 p.m.

Thanks @miconda. I still have the same issue with 5.1, but I'll try from scratch, working my way up from a basic config to try and isolate the problem further.

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-422205809

Anthony Messina

22 Nov 22 Nov

2:30 a.m.

...

Got a bit of time to test this with latest master and it seems to work with following basic config:

#!KAMAILIO

####### Global Parameters #########

### LOG Levels: 3=DBG, 2=INFO, 1=NOTICE, 0=WARN, -1=ERR
debug=2
log_stderror=no

memdbg=5
memlog=5

log_facility=LOG_LOCAL0
log_prefix="{$mt $hdr(CSeq) $ci} "

/* number of SIP routing processes */
children=2

log_engine_type="systemd"

####### Modules Section ########

/* set paths to location of modules */
# mpath="/usr/local/lib/kamailio/modules/"

loadmodule "log_systemd.so"
loadmodule "jsonrpcs.so"
loadmodule "kex.so"
loadmodule "corex.so"
loadmodule "tm.so"
loadmodule "tmx.so"
loadmodule "sl.so"
loadmodule "rr.so"
loadmodule "pv.so"
loadmodule "maxfwd.so"
loadmodule "textops.so"
loadmodule "siputils.so"
loadmodule "xlog.so"
loadmodule "sanity.so"
loadmodule "ctl.so"
loadmodule "cfg_rpc.so"
loadmodule "counters.so"



####### Routing Logic ########


/* Main SIP request routing logic
 * - processing of any incoming SIP request starts with this route
 * - note: this is the same as route { ... } */
request_route {
   xlog("===== test xlog message - R-URI is $ru\n");
   sd_journal_print("LOG_ERR", "+++++ test sysd message - R-URI is $ru\n");
   sl_send_reply("200", "ok");
   exit;
}

I sent test packets with sipsak, and in journalctl I see:

root@portugal ~ # journalctl -f
-- Logs begin at Tue 2018-09-11 19:12:04 CEST. --
Sep 17 12:14:06 portugal kamailio[4540]: INFO: <core> [core/udp_server.c:205]: probe_max_receive_buffer(): SO_RCVBUF is finally 425984
Sep 17 12:14:06 portugal kamailio[4540]: INFO: <core> [core/udp_server.c:153]: probe_max_receive_buffer(): SO_RCVBUF is initially 212992
Sep 17 12:14:06 portugal kamailio[4540]: INFO: <core> [core/udp_server.c:205]: probe_max_receive_buffer(): SO_RCVBUF is finally 425984
Sep 17 12:14:06 portugal kamailio[4553]: INFO: jsonrpcs [jsonrpcs_sock.c:443]: jsonrpc_dgram_process(): a new child 0/4553
Sep 17 12:14:06 portugal kamailio[4554]: INFO: ctl [io_listener.c:214]: io_listen_loop(): io_listen_loop:  using epoll_lt io watch method (config)
Sep 17 12:14:48 portugal kamailio[4541]: ERROR: {1 1 OPTIONS 1446075015@127.0.1.1} <script>: ===== test xlog message - R-URI is sip:test@127.0.0.1
Sep 17 12:14:48 portugal kamailio[4541]: +++++ test sysd message - R-URI is sip:test@127.0.0.1
Sep 17 12:17:01 portugal CRON[4567]: pam_unix(cron:session): session opened for user root by (uid=0)
Sep 17 12:17:01 portugal CRON[4568]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Sep 17 12:17:01 portugal CRON[4567]: pam_unix(cron:session): session closed for user roo
Sep 17 12:20:00 portugal kamailio[4542]: ERROR: {1 1 OPTIONS 306190950@127.0.1.1} <script>: ===== test xlog message - R-URI is sip:test@127.0.0.1
Sep 17 12:20:00 portugal kamailio[4542]: +++++ test sysd message - R-URI is sip:test@127.0.0.1

Kamailio was compiled and started from source tree with:

 ./src/kamailio -f ../etc/kamailio-logsystemd.cfg -L src/modules/ -a no

I've tried this again--part of the issue is related to multiple `listener=` lines. If you update the config above to add ``` listen=lo listen=eno1 ``` `log_engine_type="systemd"` will fail.

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-557359980

sergey-safarov

4:56 a.m.

I tested master branch and found feature is worked as expect. Tested with with one and multiple listeners. Goes to add log_systemd.so to rpm packaging

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-557388919

sergey-safarov

5:23 a.m.

If found if kamailio started from command line like `kamailio -DD -E` and present `log_engine_type="systemd"`, then i can see messages from `sd_journal_print` and `xlog` functions.

When I start kamailio with same config as systemd service then I not see messages from `sd_journal_print` and `xlog` functions.

When I disable `log_engine_type="systemd"` then i can see output of `sd_journal_print` and `xlog` functions again. Think some issue exist here.

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-557394219

Anthony Messina

6:15 a.m.

...

If found if kamailio started from command line like `kamailio -DD -E` and present `log_engine_type="systemd"`, then i can see messages from `sd_journal_print` and `xlog` functions.

When I start kamailio with same config as systemd service then I not see messages from `sd_journal_print` and `xlog` functions.

When I disable `log_engine_type="systemd"` then i can see output of `sd_journal_print` and `xlog` functions again. Think some issue exist here.

That is exactly what I find as well. I'm re-researching this as well as the new `systemdops.so` module to support `sd_notify()` in 0c48e1621c88bf1d390e4cfb82e52b2d6339b837. Both of them seem to suffer from the same issue -- the way Kamailio is forking interferes with the core using certain modules, as they relate to sending messages to systemd.

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/799#issuecomment-557405557

1920

Age (days ago)

3071

Last active (days ago)

sr-dev@lists.kamailio.org

16 comments

3 participants

tags (0)

participants (3)

Anthony Messina
Daniel-Constantin Mierla
sergey-safarov