[Freeswitch-users] FreeSWITCH not answering some REGISTERs

Wed Mar 22 14:59:49 MSK 2017

Hi,

That's very strange. Especially for options as the fsw reply 200 ok without any specific check (actually, only if the profile param sip-options-respond-503-on-busy is not set. You may re-test after disabling this param if it is set, but I am not sure it will make any difference.)

Have you noticed any difference between the failed REGISTER or OPTIONS requests and the normal ones?
Is it happening only for one customer or indifferently?
Also you said that you had no pb with another profile running on port 5080. Is it possible for you to test a failing customer with that profile?

Best Regards,
-- 
Vallimamod Abdullah
SIP Solutions
vma at sipsolutions.fr
tel:+33662606897
.

> On 22 Mar 2017, at 11:57, David Ponzone <david.ponzone at ipeva.fr> wrote:
> 
> I can now confirm that while FS does not reply to REGISTER/OPTIONS/NOTIFY requests, it replies to INVITE/CANCEL requests normally.
> 
> David Ponzone  Direction Technique
> email: david.ponzone at ipeva.fr
> tel:      01 74 03 18 97
> gsm:   06 66 98 76 34
> 
> Service Client IPeva
> tel:      0811 46 26 26
> www.ipeva.fr  -   www.ipeva-studio.com
> 
> Ce message et toutes les pièces jointes sont confidentiels et établis à l'intention exclusive de ses destinataires. Toute utilisation ou diffusion non autorisée est interdite. Tout message électronique est susceptible d'altération. IPeva décline toute responsabilité au titre de ce message s'il a été altéré, déformé ou falsifié. Si vous n'êtes pas destinataire de ce message, merci de le détruire immédiatement et d'avertir l'expéditeur.
> 
> 
> 
> 
>> Le 22 mars 2017 à 08:22, David Ponzone <david.ponzone at ipeva.fr> a écrit :
>> 
>> I use purely static config files for directory.
>> I upgraded to 1.6.15 and moved core-db to tmpfs, and interestingly, the issue is still there.
>> It  just happened in front of my eyes (I have a tail -F log/freeswitch.log | grep 'existing REGISTER’ running, and a tshark on port 5070 at the same time).
>> 
>> David Ponzone  Direction Technique
>> email: david.ponzone at ipeva.fr
>> tel:      01 74 03 18 97
>> gsm:   06 66 98 76 34
>> 
>> Service Client IPeva
>> tel:      0811 46 26 26
>> www.ipeva.fr  -   www.ipeva-studio.com
>> 
>> Ce message et toutes les pièces jointes sont confidentiels et établis à l'intention exclusive de ses destinataires. Toute utilisation ou diffusion non autorisée est interdite. Tout message électronique est susceptible d'altération. IPeva décline toute responsabilité au titre de ce message s'il a été altéré, déformé ou falsifié. Si vous n'êtes pas destinataire de ce message, merci de le détruire immédiatement et d'avertir l'expéditeur.
>> 
>> 
>> 
>> 
>>> Le 21 mars 2017 à 14:27, Vallimamod Abdullah <vma at vallimamod.org> a écrit :
>>> 
>>> Hi,
>>> 
>>> The sofia::register_attempt is sent just after authenticating the user. So the 5s delay you have would imply that freeswitch is having trouble getting the directory data. It would also explain the retransmission logs you see in libsofia.
>>> 
>>> Do you use xml-curl or any dynamic directory lookup? If not, the best move is, as you said, to update to latest 1.6 with tmpfs core-db and test again.
>>> 
>>> Best Regards,
>>> -- 
>>> Vallimamod Abdullah
>>> SIP Solutions
>>> vma at sipsolutions.fr
>>> tel:+33662606897
>>> .
>>> 
>>>> On 21 Mar 2017, at 10:03, David Ponzone <david.ponzone at ipeva.fr> wrote:
>>>> 
>>>> Abdullah,
>>>> 
>>>> Actually, I have the ESL events (sofia::register_attempt and sofia::register) but they show up 5 seconds after the initial REGISTER.
>>>> When they show up, I can see the 200 OK being sent to the client right away.
>>>> So it’s like nua_application_event is calling the mod_sofia callback with a delay.
>>>> 
>>>> I can also confirm that during this frozen moment, another profile listening on port 5080 is normally answering to INVITE requests.
>>>> This would suggest that the issue is related only to this specific profile listening on 5070, not to all profiles.
>>>> 
>>>> I will move core-db to tmpfs, as anyway it can only improve the overall performances.
>>>> I will then upgrade to latest 1.6.
>>>> Unless you see another option…
>>>> I am opened to suggestions as it’s possible that some debug/logging is currently missing in FS as the logs should say why it’s stalling for 4-5 seconds.
>>>> It’s not having a significant impact at the moment, so I can « play » a little bit with it.
>>>> 
>>>> David Ponzone  Direction Technique
>>>> email: david.ponzone at ipeva.fr
>>>> tel:      01 74 03 18 97
>>>> gsm:   06 66 98 76 34
>>>> 
>>>> Service Client IPeva
>>>> tel:      0811 46 26 26
>>>> www.ipeva.fr  -   www.ipeva-studio.com
>>>> 
>>>> Ce message et toutes les pièces jointes sont confidentiels et établis à l'intention exclusive de ses destinataires. Toute utilisation ou diffusion non autorisée est interdite. Tout message électronique est susceptible d'altération. IPeva décline toute responsabilité au titre de ce message s'il a été altéré, déformé ou falsifié. Si vous n'êtes pas destinataire de ce message, merci de le détruire immédiatement et d'avertir l'expéditeur.
>>>> 
>>>> 
>>>> 
>>>> 
>>>>> Le 19 mars 2017 à 14:35, Vallimamod Abdullah <vma at vallimamod.org> a écrit :
>>>>> 
>>>>> Hi,
>>>>> 
>>>>>> nta.c:3012 agent_recv_request() nta: OPTIONS (102) going to existing OPTIONS transaction
>>>>>> nta.c:3012 agent_recv_request() nta: REGISTER (116849) going to existing REGISTER transaction
>>>>> 
>>>>> These means that sofia is considering these requests as retransmissions (transaction found in sofia's internal htable). In this case, you should also see a retransmission log like "nta: re-received %s request, retransmitting %u reply".
>>>>> 
>>>>> The nua_application_event is calling a mod_sofia callback for incoming register request. So it looks like mod_sofia does not answer for some reason.
>>>>> Can you check if you get the following esl custom events: "sofia::register_attempt", "sofia::pre_register" and "sofia::register" for the failed register? It will help to tell at which point the processing stops.
>>>>> 
>>>>> Also, is your core-db in-memory? If not, you may try to move it in ram.
>>>>> 
>>>>> Best Regards,
>>>>> Vallimamod
>>>>> .
>>>>> 
>>>>> -- 
>>>>> Vallimamod Abdullah
>>>>> SIP Solutions
>>>>> vma at sipsolutions.fr
>>>>> tel:+33662606897
>>>>> .
>>>>> 
>>>>>> On 18 Mar 2017, at 20:04, David Ponzone <david.ponzone at ipeva.fr> wrote:
>>>>>> 
>>>>>> Mike,
>>>>>> 
>>>>>> with sofia loglevel all 9, I can see that sometimes (frequency hard to guess), during 4-5 secondes, FS writes those messages in the log for each REGISTER or OPTIONS request:
>>>>>> 
>>>>>> nta.c:3012 agent_recv_request() nta: OPTIONS (102) going to existing OPTIONS transaction
>>>>>> nta.c:3012 agent_recv_request() nta: REGISTER (116849) going to existing REGISTER transaction
>>>>>> 
>>>>>> It’s like it considers it’s already dealing with a such request (which it never replied to).
>>>>>> 
>>>>>> A typical regular flow of logs for a REGISTER which was responded to is:
>>>>>> 
>>>>>> nta.c:3085 agent_recv_request() nta: REGISTER (108692) 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::0x7fda40001930, 0x7fda40001130, 0x7fda40039330) called
>>>>>> soa.c:403 soa_set_params() soa_set_params(static::0x7fda40207f40, ...) called
>>>>>> nua_stack.c:271 nua_stack_event() nua(0x7fda40039330): 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
>>>>>> nua.c:879 nua_respond() nua: nua_respond: entering
>>>>>> nua_stack.c:529 nua_signal() nua(0x7fda40039330): sent signal r_respond
>>>>>> nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
>>>>>> nua_stack.c:529 nua_signal() nua(0x7fda40039330): sent signal r_destroy
>>>>>> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
>>>>>> nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
>>>>>> nua_stack.c:573 nua_stack_signal() nua(0x7fda40039330): recv signal r_respond 200 OK
>>>>>> 
>>>>>> When it fails to respond, it is:
>>>>>> 
>>>>>> nta.c:3085 agent_recv_request() nta: REGISTER (108693) 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::0x7fda40001930, 0x7fda40001130, 0x7fda402dc590) called
>>>>>> soa.c:403 soa_set_params() soa_set_params(static::0x7fda4014f880, ...) called
>>>>>> nua_stack.c:271 nua_stack_event() nua(0x7fda402dc590): event i_register 100 Trying
>>>>>> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
>>>>>> 
>>>>>> It’s difficult to know which lines are related in the log, but when FS does not answer the 200 OK, I am definitely missing a line like:
>>>>>> 
>>>>>> nua_stack.c:529 nua_signal() nua(0x7fda40039330): sent signal r_respond
>>>>>> 
>>>>>> 
>>>>>> David Ponzone  Direction Technique
>>>>>> email: david.ponzone at ipeva.fr
>>>>>> tel:      01 74 03 18 97
>>>>>> gsm:   06 66 98 76 34
>>>>>> 
>>>>>> Service Client IPeva
>>>>>> tel:      0811 46 26 26
>>>>>> www.ipeva.fr  -   www.ipeva-studio.com
>>>>>> 
>>>>>> Ce message et toutes les pièces jointes sont confidentiels et établis à l'intention exclusive de ses destinataires. Toute utilisation ou diffusion non autorisée est interdite. Tout message électronique est susceptible d'altération. IPeva décline toute responsabilité au titre de ce message s'il a été altéré, déformé ou falsifié. Si vous n'êtes pas destinataire de ce message, merci de le détruire immédiatement et d'avertir l'expéditeur.
>>>>>> 
>>>>>> 
>>>>>> 
>>>>>> 
>>>>>>> Le 17 mars 2017 à 23:08, Michael Jerris <mike at jerris.com> a écrit :
>>>>>>> 
>>>>>>> you can try sofia loglevel all 9
>>>>>>> 
>>>>>>> see if that tells you anything when we get one we don't respond to...  also get latest 1.6 and see if that helps 
>>>>>>> On Fri, Mar 17, 2017 at 5:19 PM David Villasmil <david.villasmil.work at gmail.com> wrote:
>>>>>>> How's the memory use?
>>>>>>> On Fri, Mar 17, 2017 at 10:09 PM David Ponzone <david.ponzone at ipeva.fr> wrote:
>>>>>>> All,
>>>>>>> 
>>>>>>> I noticed recently that sometimes FS (1.6.6) does not honor REGISTER or OPTIONS requests coming from some customers.
>>>>>>> Those customers register every 30 seconds, and FS does not answer to around 20-30 REGISTERs each day.
>>>>>>> I am trying to understand that, as the server is far from loaded (max 100 concurrent calls on a Dell R610).
>>>>>>> 
>>>>>>> Can anyone recommend some debugging steps to try to narrow this down ?
>>>>>>> Any known issue of this sort in 1.6.6 ?
>>>>>>> 
>>>>>>> Thank you
>>>>>>> 
>>>>>>> David Ponzone  Direction Technique
>>>>>>> email: david.ponzone at ipeva.fr
>>>>>>> tel:      01 74 03 18 97
>>>>>>> gsm:   06 66 98 76 34
>>>>>>> 
>>>>>>> Service Client IPeva
>>>>>>> tel:      0811 46 26 26
>>>>>>> www.ipeva.fr  -   www.ipeva-studio.com
>>>>>>> 
>>>>>>> Ce message et toutes les pièces jointes sont confidentiels et établis à l'intention exclusive de ses destinataires. Toute utilisation ou diffusion non autorisée est interdite. Tout message électronique est susceptible d'altération. IPeva décline toute responsabilité au titre de ce message s'il a été altéré, déformé ou falsifié. Si vous n'êtes pas destinataire de ce message, merci de le détruire immédiatement et d'avertir l'expéditeur.
>>>>>>> 