[Freeswitch-users] Internal Interface suddenly freezes

Thu Apr 15 07:04:33 UTC 2021

Hey guys,

Its still happening.
I tried to set cacheable=true to reduce the calls to my register.lua. ( In case It was the register.lua causing all of this )
But it seems like that’s not helping too. The internal interface freezes about as much as often as before…

I guess my register.lua I sent doesn’t have any obvious mistakes too …

Is it possible that some failed database-connection doesn’t get re-established, and that’s holding up the whole registration-queue?
Does anybody know where I could set freeswitch-db-reestablish timeouts? :D
Or does that even exist?

Regards,
Stefan

On 01.04.2021, at 21:54, Stefan Kainz <S.Kainz at wnt.at<mailto:S.Kainz at wnt.at>> wrote:

Hey,

I also thought of the load at first, but I set up a new server with only about 20 extensions on it.
So it looks like its not because of the load … The concurrent calls never exceed 10.

Its strange … im thinking of rewriting my register.lua from ground up, and get rid of things I don’t need.

Regards,
Stefan

On 01.04.2021, at 18:40, Peter Steinbach <lists at telefaks.de<mailto:lists at telefaks.de>> wrote:

I think, I have a similar problem with registers (and presence) via XML-Curl. Freswitch is not sending a Curl request to the server then (as we grepped on the network interface).

This happens under high load with a lot of presence involved. Suddenly Freeswitch internal profile stops responding and after a while (some minutes) it responds again. During that time, no register requests are answered at all. Only a few XML-Curl requests are sent to the server, but they do not contain the user info (which are needed for registrations) and are related to mod_voicemail.c etc.

My debug log looks like this

tport.c:3286 tport_tsend() tport_tsend(0x7f9c68005470) tpn = */xx.xxx.xxx.x:39672
tport.c:4075 tport_resolve() tport_resolve addrinfo = xx.xxx.xxx.x:39672
tport.c:4709 tport_by_addrinfo() tport_by_addrinfo(0x7f9c68005470): not found by name */xx.xxx.xxx.x:39672
tport.c:3623 tport_vsend() tport_vsend(0x7f9c68005470): 1065 bytes of 1065 to udp/xx.xxx.xxx.x:39672
tport.c:3521 tport_send_msg() tport_vsend returned 1065
nta.c:8348 outgoing_send() nta: sent NOTIFY (304240670) to */xx.xxx.xxx.x:39672
tport.c:4189 tport_pend() tport_pend(0x7f9c68005470): pending 0x7f9997dcf880 for udp/xxx.xx.x.xxx:5060 (already 124658)
nua_stack.c:569 nua_stack_signal() nua(0x7f9a0bd45ae0): recv signal r_notify
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f9c68001b90, 0x7f9c68001390, 0x7f9a0bd45ae0) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f9997dd1c90, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f9997dd1c90, ...) called
nta.c:4446 nta_leg_tcreate() nta_leg_tcreate(0x7f9997dcd870)
nta.c:2694 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3286 tport_tsend() tport_tsend(0x7f9c68005470) tpn = udp/xx.xxx.xxx.x:58694
tport.c:4075 tport_resolve() tport_resolve addrinfo = xx.xxx.xxx.x:58694
tport.c:4709 tport_by_addrinfo() tport_by_addrinfo(0x7f9c68005470): not found by name udp/xx.xxx.xxx.x:58694
tport.c:3623 tport_vsend() tport_vsend(0x7f9c68005470): 1114 bytes of 1114 to udp/xx.xxx.xxx.x:58694
tport.c:3521 tport_send_msg() tport_vsend returned 1114
nta.c:8348 outgoing_send() nta: sent NOTIFY (304240671) to udp/xx.xxx.xxx.x:58694
tport.c:4189 tport_pend() tport_pend(0x7f9c68005470): pending 0x7f9997dd2650 for udp/xxx.xx.x.xxx:5060 (already 124659)

Looks like some event queue is stuck?

/Peter

Am 01.04.21 um 00:10 schrieb Stefan Kainz:
Hi guys,

Me again.
It just happened again :)
( With extra debugging lines in my register.lua and a not found xml like you suggested if the result is empty )

This time I turned up the logging to 9 while it was happening.
This is what I found:

While its happening, a Register request causes the following to be logged:

nta.c:2880 agent_recv_request() nta: received REGISTER sip:xxxxx SIP/2.0 (CSeq 73038)
nta.c:3012 agent_recv_request() nta: REGISTER (73038) going to existing REGISTER transaction
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7fab1c0042b0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7fab1c0042b0)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7fab1c0042b0) msg 0x7fab1d095280 from (udp/xxx.xxx.xxx.xxx:5060) has 809 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7fab1c0042b0): msg 0x7fab1d095280 (809 bytes) from udp/xxx.xxx.xxx.xxx:5060/sip next=(nil)

And that’s it. it doesn’t even execute my register.lua anymore, I just tries to update an existing Register transaction.
When I start an ngrep on port 5060, all I see is the register, no unauthorised or ok response.

While a Register Request after I restarted freeswitch and everything worked again looks like this:

nta.c:2880 agent_recv_request() nta: received REGISTER sip:xxxxx SIP/2.0 (CSeq 37884)
nta.c:3085 agent_recv_request() nta: REGISTER (37884) going to a default leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:899 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f8514001930, 0x7f8514001130, 0x7f85142225b0) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f85141f6f70, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f85142225b0): event i_register 100 Trying
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2021-03-31 23:47:11.485911 [INFO] switch_cpp.cpp:1328 register.lua: Connect to database
...

The last entry “Connect to database” is already a consoleLog from my register.lua.
From here on out everything works great again …

So, do you think it could still be true that one request to my register.lua holds up all subsequent requests?

Thank you very much!

Regards,

On 31.03.2021, at 09:16, Stefan Kainz <s.kainz at wnt.at<mailto:s.kainz at wnt.at>> wrote:

Ok thanks!

I will try to return a not found and add debug lines to the register.lua.
I will let you know If that helped.

Regards,
Stefan

On 30.03.2021, at 21:49, Bote Man <botelist at gmail.com<mailto:botelist at gmail.com>> wrote:

And add some logging lines to the Lua script so that it can tell you what is happening at each stage. Perhaps it is doing something that you don’t want it to do, or not doing something that you do want it to do?

Bote

From: FreeSWITCH-users <freeswitch-users-bounces at lists.freeswitch.org<mailto:freeswitch-users-bounces at lists.freeswitch.org>> On Behalf Of Mircea Botoca-Huh
Sent: Tuesday, 30 March, 2021 15:21
To: FreeSWITCH Users Help <freeswitch-users at lists.freeswitch.org<mailto:freeswitch-users at lists.freeswitch.org>>
Subject: Re: [Freeswitch-users] Internal Interface suddenly freezes

Hi,

If you don't wish to serve an action from your Lua script, you must return not found.

This is from confluence doc:

If your LUA application receives a request and you don't wish to serve dialplan or like to fallback to plain XML dialplan, then you should return the following "not found" result.

<?xml version="1.0" encoding="UTF-8" standalone="no"?>

<document type="freeswitch/xml">

  <section name="result">

    <result status="not found" />

  </section>

</document>

Best regards,
Mircea

mar., 30 mar. 2021, 22:05 Stefan Kainz <s.kainz at wnt.at<mailto:s.kainz at wnt.at>> a scris:
Hi,

The lua script is called on a directory request.
Your know, autoload_configs, lua.conf.xml:

<param name="xml-handler-script" value="register.lua"/>
<param name="xml-handler-bindings" value="directory,dialplan”/>

Maybe the dialplan in the xml-handler-bindings is doing something I don’t want …

In the register.lua I do basic sanity checks, and of course a database query that returns the user-data.
After that I generate the xml that gets sent to freeswitch.

Yesterday I added cacheable=“120" to the <user> tag.
Thats no solution of course, but it looks like when the data is in the cache the lua script doesn’t get called.
So maybe the error won’t occur as often as before …

But, I have an idea, maybe you can confirm this.
With dialplan enabled in xml-handler-bindings, the lua script is also called on calls, not just on registrations.
( I think that’s necessary to authenticate the users on an outgoing call, please correct me if im wrong )
In the register.lua I only handle directory-requests and action==user_call.
All other requests to my register.lua are unhandled and therefore I don’t return any xml at all.

Maybe I get a request to my register.lua that is not a directory-request and not a user_call and since I don’t return a xml, Sofia hangs.

Does that sound plausible?

Thank you in advance!

Regards,
Stefan

On 29.03.2021, at 23:57, David Villasmil <david.villasmil.work at gmail.com<mailto:david.villasmil.work at gmail.com>> wrote:

That was going to be my next question: what’s lua doing and at what point?

On Mon, 29 Mar 2021 at 16:09, Stefan Kainz <s.kainz at wnt.at<mailto:s.kainz at wnt.at>> wrote:
I just found an issue on jira, where it seems someone had the same problem I have.
https://freeswitch.org/jira/browse/FS-3328
I don’t have mod_xml_curl enabled though.

But knowing that sofia can handle only one register at a time and then blocking all subsequent Registers is a good starting point …

Regards,

Von: FreeSWITCH-users <freeswitch-users-bounces at lists.freeswitch.org<mailto:freeswitch-users-bounces at lists.freeswitch.org>> Im Auftrag von Bote Man
Gesendet: Montag, 29. März 2021 15:45
An: 'FreeSWITCH Users Help' <freeswitch-users at lists.freeswitch.org<mailto:freeswitch-users at lists.freeswitch.org>>
Betreff: Re: [Freeswitch-users] Internal Interface suddenly freezes

The one common element is your Lua script.

I am certainly no expert on script writing, but I have seen a number of problems on the mailing list over the years with scripts doing “too much” work during critical sections of the dialplan. Perhaps there is a race condition?

Hope this helps.

---
John Boteler
BnC Group U.S.A.

From: FreeSWITCH-users <freeswitch-users-bounces at lists.freeswitch.org<mailto:freeswitch-users-bounces at lists.freeswitch.org>> On Behalf Of Stefan Kainz
Sent: Monday, 29 March, 2021 07:49
To: FreeSWITCH Users Help <freeswitch-users at lists.freeswitch.org<mailto:freeswitch-users at lists.freeswitch.org>>
Subject: Re: [Freeswitch-users] Internal Interface suddenly freezes

Thank you for your answer!

Hmm, I also tested it on two completely different servers ( no virtualization ) and the problem exists on both.
Im also going to try it on a third server, also completely different, but I cant really image that this is a hardware-thing …

We also have many freeswitch servers in production ( Exactly the same hardware as the server with the problem ).
The only difference is that one of those servers handles registrations, and one doesn’t.
The one handling the registrations has the problem, the other one doesn’t.

Its really strange …

Regards,

Von: FreeSWITCH-users <freeswitch-users-bounces at lists.freeswitch.org<mailto:freeswitch-users-bounces at lists.freeswitch.org>> Im Auftrag von David Villasmil
Gesendet: Montag, 29. März 2021 13:12
An: FreeSWITCH Users Help <freeswitch-users at lists.freeswitch.org<mailto:freeswitch-users at lists.freeswitch.org>>
Betreff: Re: [Freeswitch-users] Internal Interface suddenly freezes

That looks to be more on the hardware side than software. It’d be an extremely coincidence those versions and all those OS have some issue somewhere.
Change hardware.

On Sun, 28 Mar 2021 at 09:12, Stefan Kainz <s.kainz at wnt.at<mailto:s.kainz at wnt.at>> wrote:
Hi everbody,

I have a little bit of a problem.
Im using Version 1.10.3. ( but this problem also occurs on version 1.4.18 )

Sometimes the internal Sofia interface just stops responding to SIP Requests.
It sometimes happens once every day, and sometimes once a week.
It happens at completely random times, like one day in the morning, and the next day in the middle of the night.
The freeswitch.log gives me nothing, its like the Sofia interface was stopped.

When I try to restart the interface with "sofia profile internal restart” nothing happens. The fs_cli just remains stuck with that command.

The solution is to restart the freeswitch service.

Sometimes when I recognise it too late, for example in the middle of the night, it seems like the problem solves itself after about 2 hours.
The profile just starts working again, without somebody doing anything.

I have checked a variety of things, including the firewall & fail2ban, network connection, made sure watchdog is disabled, and also tested it on different Debian-versions and freeswitch versions.
It seems this problem occurs on every freeswitch version i have tested.

The external-profile on the other hand, keeps working like nothing happened.

Both Interfaces listen on the same network-device with a public ip.
The only difference is, the internal profile uses a Lua file to handle registrations.

Has anybody come across anything similar?

Any help is much appreciated!

Regards,

_________________________________________________________________________