<div dir="ltr">Hi again.<br>Guys I need some hints from you, at least personally, so please take a look at my first message if possible.<br>Thanks in advance and have a nice day.<div class="gmail_extra"><br><div class="gmail_quote">2018-07-16 10:34 GMT+03:00 Donat Zenichev <span dir="ltr"><<a href="mailto:donat.zenichev@gmail.com" target="_blank">donat.zenichev@gmail.com</a>></span>:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Hi community, recently I've got the problems with sudden termination of the daemon.<br><br><div>This bunch of similar rows seems to be some timer job that takes longer than it was supposed to be:</div><div>Jul 14 02:13:10 some-machine opensips[25060]: message repeated 3 times: [ WARNING:core:timer_ticker: timer task <nh-timer> already schedualed for 10040133060 ms (now 10040134050 ms), it may overlap..]</div><div>Jul 14 08:45:29 some-machine opensips[25060]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for 10063404100 ms (now 10063404200 ms), it may overlap..</div><div>Jul 14 08:45:29 some-machine opensips[25060]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for 10063404200 ms (now 10063404300 ms), it may overlap..</div><div>Jul 14 08:45:29 some-machine opensips[25060]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for 10063404300 ms (now 10063404400 ms), it may overlap..</div><div>Jul 14 08:45:30 some-machine opensips[25060]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for 10063404400 ms (now 10063404500 ms), it may overlap..</div><div>Jul 14 08:45:30 some-machine opensips[25060]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for 10063404500 ms (now 10063404600 ms), it may overlap..</div><div>Jul 14 08:45:30 some-machine opensips[25060]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for 10063404600 ms (now 10063404700 ms), it may overlap..</div><div>Jul 14 08:45:30 some-machine opensips[25060]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for 10063404700 ms (now 10063404800 ms), it may overlap..</div><div>Jul 14 08:45:30 some-machine opensips[25060]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for 10063404800 ms (now 10063404900 ms), it may overlap..</div><div>Jul 14 08:45:30 some-machine opensips[25060]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for 10063404900 ms (now 10063405010 ms), it may overlap..</div><div>Jul 14 08:45:30 some-machine opensips[25060]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for 10063405010 ms (now 10063405110 ms), it may overlap..</div><div>Jul 14 08:45:30 some-machine opensips[25077]: CRITICAL:core:receive_fd: EOF on 41</div><div>Jul 14 08:45:30 some-machine opensips[25060]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for 10063405110 ms (now 10063405210 ms), it may overlap..</div><div>Jul 14 08:45:30 some-machine opensips[25060]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for 10063405210 ms (now 10063405310 ms), it may overlap..</div><div>Jul 14 08:45:30 some-machine opensips[25060]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for 10063405310 ms (now 10063405410 ms), it may overlap..</div><div>Jul 14 08:45:31 some-machine opensips[25060]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for 10063405410 ms (now 10063405510 ms), it may overlap..</div><div><br></div><div>Then we have the following row, that means that child process 25075 was killed by SIGSEGV signal (probably this process tried to appeal to non-existent memory cell?).</div><div>Jul 14 08:45:31 some-machine opensips[25054]: INFO:core:handle_sigs: child process 25075 exited by a signal 11</div><div><br></div><div>I can see in the logs lots of rows about the process 25075 that was treating the nathelper module:</div><div>Jul 14 08:45:28 some-machine opensips[25075]: ERROR:nathelper:msg_send: send() for proto 2 failed</div><div>Jul 14 08:45:28 some-machine opensips[25075]: ERROR:nathelper:nh_timer: sip msg_send failed</div><div>Jul 14 08:45:28 some-machine opensips[25075]: ERROR:nathelper:msg_send: send() for proto 2 failed</div><div>Jul 14 08:45:28 some-machine opensips[25075]: ERROR:nathelper:nh_timer: sip msg_send failed</div><div><br></div><div>Then we have a core dump generated</div><div>Jul 14 08:45:31 some-machine opensips[25054]: INFO:core:handle_sigs: core was generated</div><div><br></div><div>Then we have a SIGCHLD</div><div>Jul 14 08:45:31 some-machine opensips[25054]: INFO:core:handle_sigs: terminating due to SIGCHLD</div><div><br></div><div>I'm not sure how this is considered by opensips daemon (afaik a root process can ignore such requests) but seems that it caused a termination of the root process as well.</div><div>Because just after that we see, that a SIGTERM (killing) for all the forked processes had started:</div><div>Jul 14 08:45:31 some-machine opensips[25054]: INFO:core:handle_sigs: terminating due to SIGCHLD</div><div>Jul 14 08:45:31 some-machine opensips[25074]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25077]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25070]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25064]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25072]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25062]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25060]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25056]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25067]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25065]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25061]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25063]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25066]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25068]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25076]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25069]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25071]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25073]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25058]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25059]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25057]: INFO:core:sig_usr: signal 15 received</div><div>Jul 14 08:45:31 some-machine opensips[25054]: INFO:core:cleanup: cleanup</div><div><br></div><div>And it's bizarre, since just one killed sub-process triggered such general termination.</div><div><br></div><div>Since we see that, the process 25075 was related to nathelper module, the problem perhaps is around that.</div><div>I've read several bug articles on the similar issues, and one of the answers (from Razvan Crainea) seems to be relevant to our story:</div><div><br></div><div>"OpenSIPS pings all users in a single timer run. If there are a lot of</div><div>users, this might take a lot, especially if users are using TCP, and</div><div>some of them have a stale connection.</div><div>Increasing the natping_partitions partitions will basically split all</div><div>the users in smaller sets, and will spread them among multiple job runs,</div><div>thus multiple processes. Therefore increasing this parameter will</div><div>definitely help you.</div><div>The range is not a magic value . It depends on the amount of users,</div><div>bandwidth, etc. It makes sense to set this parameter from 1 to the</div><div>maximum number of processes provisioned - anything else will probably</div><div>make timer jobs overlap. "</div><div><br></div><div>For now we do have this parameter set to:</div><div>modparam("nathelper", "natping_partitions", 4)</div><div><br></div><div>So it performs nat pinging separately, each part has 1/4 part of users.</div><div><br></div><div>Actually it seems pretty enough to work properly, but seems that nathelper accumulates the "dead" users (that are not available anymore) and tries to ping them. But it's just my assumption, because we have to many rows with the same error (not only this time and with this child process, they are spread all a log), I mean like that:</div><div>Jul 14 08:45:28 some-machine opensips[25075]: ERROR:nathelper:msg_send: send() for proto 2 failed</div><div>Jul 14 08:45:28 some-machine opensips[25075]: ERROR:nathelper:nh_timer: sip msg_send failed</div><div><br></div><div>And parameters that can have an impact on this situation:<br><div>modparam("nathelper", "natping_interval", 30)</div><div>modparam("nathelper", "natping_partitions", 4)</div></div><div><br>My idea is to increase the partitions, probably to value "8" ?<br>And probably decrease the interval to 10 seconds.<br><br>What would you advice? <span class="HOEnZb"><font color="#888888"><br><br></font></span></div><span class="HOEnZb"><font color="#888888">-- <br><div class="m_8532346002776671897gmail_signature"><div dir="ltr"><div><div dir="ltr"><div dir="ltr"><div dir="ltr"><font style="background-color:rgb(255,255,255)" color="#0b5394">-- <br>BR, Donat Zenichev
<br><br></font></div></div></div></div></div></div>
</font></span></div>
</blockquote></div><br><br clear="all"><div><br></div>-- <br><div class="gmail_signature" data-smartmail="gmail_signature"><div dir="ltr"><div><div dir="ltr"><div dir="ltr"><div dir="ltr"><font style="background-color:rgb(255,255,255)" color="#0b5394">-- <br>BR, Donat Zenichev
<br><br></font></div></div></div></div></div></div>
</div></div>