Skip to content
This repository has been archived by the owner on Mar 7, 2024. It is now read-only.

Some calls failing with media timeout #122

Open
sachinlevel opened this issue Jul 19, 2023 · 24 comments
Open

Some calls failing with media timeout #122

sachinlevel opened this issue Jul 19, 2023 · 24 comments

Comments

@sachinlevel
Copy link

Hi Dave,

We are using this module (https://github.com/drachtio/drachtio-freeswitch-modules/blob/main/examples/google_transcribe.js) to trancribe calls, but some calls from drachtio to freeswitch are failing with media timeout, also i am not setting up this variable, so it should be using its default value, what could be possibly wrong and how can we correct it ?

it fails while connecting to FS, => ms.connectCaller(req, res)

/usr/local/freeswitch/log# grep -i "Timeout" freeswitch.log

2023-06-07 06:03:17.689310 [WARNING] sofia.c:5227 rtp-timeout-sec deprecated use media_timeout variable.
2023-06-07 06:03:17.689334 [WARNING] sofia.c:5234 rtp-hold-timeout-sec deprecated use media_hold_timeout variable.
2023-06-30 04:28:16.337857 [WARNING] sofia.c:5227 rtp-timeout-sec deprecated use media_timeout variable.
2023-06-30 04:28:16.337878 [WARNING] sofia.c:5234 rtp-hold-timeout-sec deprecated use media_hold_timeout variable.

db492d19-0caf-49df-8e99-330769961f85 2023-06-30 17:39:16.083379 [NOTICE] switch_core_media.c:2935 Hangup sofia/drachtio_mrf/[email protected]:5060 [CS_EXECUTE] [MEDIA_TIMEOUT]
Reason: SIP;cause=604;text="MEDIA_TIMEOUT"
c93129ab-bf73-49ea-832a-ee06b371de7e 2023-07-01 03:05:46.763366 [NOTICE] switch_core_media.c:2935 Hangup sofia/drachtio_mrf/[email protected]:5060 [CS_EXECUTE] [MEDIA_TIMEOUT]
Reason: SIP;cause=604;text="MEDIA_TIMEOUT"
2fe67026-d5a4-4c4f-bb8d-42b66fb11db7 2023-07-01 03:05:46.783374 [NOTICE] switch_core_media.c:2935 Hangup sofia/drachtio_mrf/[email protected]:5060 [CS_EXECUTE] [MEDIA_TIMEOUT]
Reason: SIP;cause=604;text="MEDIA_TIMEOUT"
69c38a74-8e67-47ce-ab33-53986d46d42f 2023-07-06 17:50:01.263340 [NOTICE] switch_core_media.c:2935 Hangup sofia/drachtio_mrf/[email protected]:5060 [CS_EXECUTE] [MEDIA_TIMEOUT]
Reason: SIP;cause=604;text="MEDIA_TIMEOUT"
2c421ff1-a6ea-4589-8c2b-9eacbd532689 2023-07-06 17:50:01.283335 [NOTICE] switch_core_media.c:2935 Hangup sofia/drachtio_mrf/[email protected]:5060 [CS_EXECUTE] [MEDIA_TIMEOUT]
Reason: SIP;cause=604;text="MEDIA_TIMEOUT"
05aef738-d580-42d6-ac27-ff37ee356654 2023-07-07 21:01:24.303403 [NOTICE] switch_core_media.c:2935 Hangup sofia/drachtio_mrf/[email protected]:5060 [CS_EXECUTE] [MEDIA_TIMEOUT]
Reason: SIP;cause=604;text="MEDIA_TIMEOUT"
4606db18-b9cc-426a-9cf1-0c08324adcd8 2023-07-07 21:01:24.383350 [NOTICE] switch_core_media.c:2935 Hangup sofia/drachtio_mrf/[email protected]:5060 [CS_EXECUTE] [MEDIA_TIMEOUT]
Reason: SIP;cause=604;text="MEDIA_TIMEOUT"
64425d08-b0ff-4a33-bfbb-ef6abec66514 2023-07-18 19:26:30.303360

Reason: SIP;cause=604;text="MEDIA_TIMEOUT"
@davehorton
Copy link
Collaborator

what version of freeswitch are you using and what linux distribution?

@sachinlevel
Copy link
Author

sachinlevel commented Jul 19, 2023

we are using this docker file https://github.com/drachtio/docker-drachtio-freeswitch-mrf/blob/main/Dockerfile

FreeSWITCH Version 1.10.5-release+git20200818T185121Z25569c1631~64bit (git 25569c1 2020-08-18 18:51:21Z 64bit)

@sachinlevel
Copy link
Author

on a ubuntu machine vm

@davehorton
Copy link
Collaborator

OK. media timeout from the freeswitch side means that it did not receive any RTP packets from the far end. It would be necessary to be able to see all the SIP signaling for a failed call, and possibly a network pcap as well. But generally this means that the far end was not able to send packets to the advertised freeswitch address. If this is intermittent I would check to be sure you have opened the full rtp port range on your server to allow incoming traffic to all of the udp ports that freeswitch is listening on

@sachinlevel
Copy link
Author

sachinlevel commented Jul 19, 2023

Hi Dave, i am not an expert with freeswitch, so we are using all the default configurations, how can we check what all ports are open for rtp ? for drachtio we have 50XX tls port open. and yes this is intermittent issue with a few calls.

@davehorton
Copy link
Collaborator

you will find the rtp min and max port range in /usr/local/freeswitch/config/autoload_configs/switch.conf.xml

In the image you are using it should be 25000-39000/udp, so make sure you are allowing all traffic in to those ports

@sachinlevel
Copy link
Author

sachinlevel commented Jul 19, 2023

So, this is what you mean by allowing traffic to this fs docker instance right ?

version: '3'

services:
  your_service_name:
    image: your_image_name:tag
    ports:
      - "25000-39000: 25000-39000/udp"

@davehorton
Copy link
Collaborator

no, I mean the server itself also needs to be configured to allow traffic in to those ports.

As far as what you have above which seems to be from a docker-compose file, it is correct as far as telling docker how to direct traffic that does make it in to those ports, but I would also comment that I have seen docker have problems and be very slow when configured to map thousands of ports like that.

@sachinlevel
Copy link
Author

yeah my FS server allows the traffic to these port and docker is using network mode host, so you mean i need to check for these port allowed in VM or the source from where i am receiving calls ?

@davehorton
Copy link
Collaborator

correct

@sachinlevel
Copy link
Author

sachinlevel commented Jul 19, 2023

m=audio 30788 RTP/SAVP 0 101\r
m=audio 21608 RTP/SAVP 0 101\r
m=audio 21936 RTP/SAVP 0 101\r

i can see that some of the failed calls belong to the ports which are below or above the said range, how can i update this range in my configs should i add this to vars file ? with new ports but its also failing for one port that is within the range.

<param name="rtp-start-port" value="XXXX"/>
<param name="rtp-end-port" value="YYYY"/>

@davehorton
Copy link
Collaborator

I can't be sure but I think what you reprinted above is from the SDP offered by the far end? It is not relevant what ports they are sending from.

@sachinlevel
Copy link
Author

HI Dave, yes above is from SDP, i thought these are target ports, where can i get those ?
got some logs from FS, but its just saying dropping media packets and then TIMEOUT.

INVITE sip:[email protected]:5070 SIP/2.0
Via: SIP/2.0/UDP X.X.X.X;rport;branch=z9hG4bKS9p98pajpD28S
Max-Forwards: 70
From: <sip:X.X.X.X:5060>;tag=HeStvtD9p31XQ
To: <sip:[email protected]:5070>
Call-ID: 2cc7b100-920f-123c-ed99-0242ac130002
CSeq: 69519435 INVITE
Contact: <sip:X.X.X.X:5060>
User-Agent: drachtio-fsmrf:eac88f44-56db-42e2-be5a-f0decb926e03
Content-Type: application/sdp
Content-Length: 705
X-esl-outbound: 10.138.0.128:41991

v=0
o=FreeSWITCH 1688124377 1688124378 IN IP4 Y.Y.Y.Y
s=FreeSWITCH
c=IN IP4 Y.Y.Y.Y
t=0 0
m=audio 22078 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=crypto:1 AEAD_AES_256_GCM_8 inline:9vTmp+s5lA/geyXRFaiUpSBTxMLJmPRYVvXicsCSVqnionzq9cbktKmHXuc=
a=crypto:3 AEAD_AES_128_GCM_8 inline:Al3cx8cZHRsyBF1uwYlFfuxJ8hVwnOz0vcTP/A==
a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:iPPr7EAISxAFDFJ/zgiLQExrQDt3ank3ilh+wKtQqBhtT/lep2JDxOVm5bmDHA==
a=crypto:6 AES_192_CM_HMAC_SHA1_80 inline:pshcum3EWtkgo60uXRoa8q/VAdz5gN6VVrkiRYNt2bzMe3CzXEs=
a=crypto:7 AES_CM_128_HMAC_SHA1_80 inline:aKwvN1je+uj5cmdDr8w4vN67tRu2oFyP6U61VMpS
a=ptime:20

db492d19-0caf-49df-8e99-330769961f85 2023-06-30 17:34:15.183358 [NOTICE] switch_channel.c:1118 New Channel sofia/drachtio_mrf/[email protected]:5060 [db492d19-0caf-49df-8e99-330769961f85]
send 358 bytes to udp/[X.X.X.X]:5060 at 17:34:15.196634:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP X.X.X.X;rport=5060;branch=z9hG4bKS9p98pajpD28S
From: <sip:X.X.X.X:5060>;tag=HeStvtD9p31XQ
To: <sip:[email protected]:5070>
Call-ID: 2cc7b100-920f-123c-ed99-0242ac130002
CSeq: 69519435 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.10.5-release+git~20200818T185121Z~25569c1631~64bit
Content-Length: 0


db492d19-0caf-49df-8e99-330769961f85 2023-06-30 17:34:15.183358 [NOTICE] sofia_media.c:92 Pre-Answer sofia/drachtio_mrf/[email protected]:5060!
send 1115 bytes to udp/[X.X.X.X]:5060 at 17:34:15.200368:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP X.X.X.X;rport=5060;branch=z9hG4bKS9p98pajpD28S
From: <sip:X.X.X.X:5060>;tag=HeStvtD9p31XQ
To: <sip:[email protected]:5070>;tag=K36jDUpS7rppj
Call-ID: 2cc7b100-920f-123c-ed99-0242ac130002
CSeq: 69519435 INVITE
Contact: <sip:[email protected]:5070;transport=udp>
User-Agent: FreeSWITCH-mod_sofia/1.10.5-release+git~20200818T185121Z~25569c1631~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 334
Remote-Party-ID: "drachtio" <sip:[email protected]>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1688111535 1688111536 IN IP4 X.X.X.X
s=FreeSWITCH
c=IN IP4 X.X.X.X
t=0 0
m=audio 34920 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=recvonly
a=ptime:20
a=crypto:1 AEAD_AES_256_GCM_8 inline:0svnrImKjtYj5wQ5ljVlitGep5DJTo9eZjq3fHM1Z1oEDurALCJFQSzyxeM=

db492d19-0caf-49df-8e99-330769961f85 2023-06-30 17:34:15.183358 [NOTICE] mod_dptools.c:1406 Channel [sofia/drachtio_mrf/[email protected]:5060] has been answered

db492d19-0caf-49df-8e99-330769961f85 2023-06-30 17:34:15.183358 [NOTICE] mod_event_socket.c:452 Trying host: 10.138.0.128:41991
recv 338 bytes from udp/[X.X.X.X]:5060 at 17:34:15.203587:
------------------------------------------------------------------------
ACK sip:[email protected]:5070;transport=udp SIP/2.0
Via: SIP/2.0/UDP X.X.X.X;rport;branch=z9hG4bKtjg2ajUNKprUN
Max-Forwards: 70
From: <sip:X.X.X.X:5060>;tag=HeStvtD9p31XQ
To: <sip:[email protected]:5070>;tag=K36jDUpS7rppj
Call-ID: 2cc7b100-920f-123c-ed99-0242ac130002
CSeq: 69519435 ACK
Content-Length: 0


db492d19-0caf-49df-8e99-330769961f85 2023-06-30 17:35:11.563357 [ERR] audio_stream_adapter.cpp:355 (66) dropping packets!
db492d19-0caf-49df-8e99-330769961f85 2023-06-30 17:36:05.063358 [ERR] audio_stream_adapter.cpp:355 (66) dropping packets!
db492d19-0caf-49df-8e99-330769961f85 2023-06-30 17:36:59.923394 [ERR] audio_stream_adapter.cpp:355 (66) dropping packets!
db492d19-0caf-49df-8e99-330769961f85 2023-06-30 17:37:53.943431 [ERR] audio_stream_adapter.cpp:355 (66) dropping packets!
db492d19-0caf-49df-8e99-330769961f85 2023-06-30 17:38:46.883364 [ERR] audio_stream_adapter.cpp:355 (66) dropping packets!
db492d19-0caf-49df-8e99-330769961f85 2023-06-30 17:39:16.083379 [NOTICE] switch_core_media.c:2935 Hangup sofia/drachtio_mrf/[email protected]:5060 [CS_EXECUTE] [MEDIA_TIMEOUT]
send 575 bytes to udp/[X.X.X.X]:5060 at 17:39:16.099107:
------------------------------------------------------------------------
BYE sip:X.X.X.X:5060 SIP/2.0
Via: SIP/2.0/UDP X.X.X.X:5070;rport;branch=z9hG4bKv2Zm84y7BDvjH
Max-Forwards: 70
From: <sip:[email protected]:5070>;tag=K36jDUpS7rppj
To: <sip:X.X.X.X:5060>;tag=HeStvtD9p31XQ
Call-ID: 2cc7b100-920f-123c-ed99-0242ac130002
CSeq: 69519586 BYE
User-Agent: FreeSWITCH-mod_sofia/1.10.5-release+git~20200818T185121Z~25569c1631~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Reason: SIP;cause=604;text="MEDIA_TIMEOUT"
Content-Length: 0


db492d19-0caf-49df-8e99-330769961f85 2023-06-30 17:39:16.103387 [NOTICE] switch_core_session.c:1744 Session 68 (sofia/drachtio_mrf/[email protected]:5060) Ended
db492d19-0caf-49df-8e99-330769961f85 2023-06-30 17:39:16.103387 [NOTICE] switch_core_session.c:1748 Close Channel sofia/drachtio_mrf/[email protected]:5060 [CS_DESTROY]


@sachinlevel
Copy link
Author

sachinlevel commented Jul 20, 2023

also the error message that i get here ms.connectCaller(req, res) is Connection timeout on the node application looks like timeout waiting for esl connection after invite to FS answered from drachtio-fsmrf code base. looks like its failing in connecting to freeswitch.

@davehorton
Copy link
Collaborator

what is audio_stream_adapter.cpp ? I don't recognize it as any code in this repo

@davehorton
Copy link
Collaborator

as far as ms.connectCaller timing out, that means that freeswitch was unable to make an outbound tcp socket connection to the drachtio-fsmrf application. Can you show me a freeswitch log for that error, including the sip messages

@sachinlevel
Copy link
Author

sachinlevel commented Jul 20, 2023

@davehorton this issue is intermittent, we are unable to reproduce it, looking for logs but is there anything we can try that could help solving this issue ? or any possible reason since 2-3 calls out of 100s are failing

@sachinlevel
Copy link
Author

Logs for Freeswitch and drachtio for a faulty call

https://gist.github.com/sachinlevel/c31a9b6c8337caf8f3f36d02bedb15c7

these are for two call invites, basically for each call we get two invites one for customer and other for agent,
in this call the Agent leg failed,
From: "Agent" sip:Agent@FAR_END_IP;tag=BmjQeHH83pr0D

@sachinlevel
Copy link
Author

@davehorton did you check the logs ? we are still facing this issue intermittently.

@sachinlevel
Copy link
Author

@davehorton these are the required details.

Drachtio logs : https://gist.github.com/sachinlevel/c31a9b6c8337caf8f3f36d02bedb15c7
Freeswitch logs : https://gist.github.com/sachinlevel/aaca04ea2bb2d2bc04a0251474c8b009
Call-ID: 74efd8b3-a1a0-123c-f9a9-42010af06a08 that failed

Request object that failed : https://gist.github.com/sachinlevel/0a80a4e8b0b4e305cf90deadf7598de1

@sachinlevel
Copy link
Author

ms.connectCaller(req, res) fails with Connection timeout, and on retrying using same ms.connectCaller(req, res) - using the same request it fails with "Response#send: final response already sent"

@byoungdale
Copy link
Contributor

The "Connection timeout" in the application log you posted is usually because Freeswitch can't reach your Node.js/drachtio-fsmrf app. Can your freeswitch reach X-esl-outbound: VM_PRIVATE_IP:39183? If it cannot, you will get that "Connection timeout" error.

See a similar issue someone had here in a drachtio-fsmrf issue

@byoungdale
Copy link
Contributor

But, the original issue you posted seemed to be something else that isn’t in the last logs you posted. So, there might be multiple issues going on here.

@sachinlevel
Copy link
Author

@byoungdale for the issue that you mentioned for them no call is connecting, for us most of the calls are connecting roughly around 3 calls per 100 calls are failing to connect to FS. was wondering why would that happen, and this issue is intermittent , if you can guide us how can we correctly retry to connect to FS, that would be helpful since retrying same request is failing with "Response#send: final response already sent"

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants