[Freeswitch-users] call drop because of no write codec, incompatible_destination
António Silva
asilva at wirelessmundi.com
Tue Nov 26 18:09:13 UTC 2019
Hi,
Actually my problem didn't get fixed.. restart freeswitch it solve the
issue but after a few days it start to reproduce again, and not for all
call is very random.
I do have a log full log with sip trace and there is nothing wrong,
codecs are negotiated OK, actually FS sends the 200OK and a few ms
latter FS it sends the bye, see SIP flow.
The call flow:
incoming --> play audio message --> dial group --> member answer (Bye,
in log the error no write codec)
There is no transcoding, the incoming call negotiate G711A as well.
I'm trying to figure out what could be causing this, but it looks there
is some lock in getting the codec ready, or something is freezing FS.
In the code, the only place where we can get this message is at
switch_core_media.c :
if (!(session->write_codec &&
switch_core_codec_ready(session->write_codec)) && !pass_cng) {
switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(session),
SWITCH_LOG_ERROR, "%s has no write codec.\n",
switch_channel_get_name(session->channel));
switch_channel_hangup(session->channel,
SWITCH_CAUSE_INCOMPATIBLE_DESTINATION);
return SWITCH_STATUS_FALSE;
}
In sofia profile i've set:
<param name="suppress-cng" value="true"/>
So, i guess the only place that is triggering this message is
switch_core_codec_ready:
static inline switch_bool_t switch_core_codec_ready(switch_codec_t *codec)
{
return (codec && (codec->flags & SWITCH_CODEC_FLAG_READY) &&
codec->mutex && codec->codec_interface && codec->implementation) ?
SWITCH_TRUE : SWITCH_FALSE;
}
Any hint to figure out the issue?
On 25/10/2019 14:43, António Silva wrote:
>
> Hi Mike,
>
> Thanks for the reply.
>
> yes, the negation codec is done correctly at least from the output
> messages in the logs.
>
>
> I found the source of the problem, for some i have multiple FS pids,
> restarting solve my problem., now there is only one. No more drop calls.
>
> The "defunct" happen because the g729 license-server wasn't fully
> started, this is a known issue, but the two main pid's no idea why.
>
> Just in case i also set in switch.xml the parameter
> threaded-system-exec" to "true".
>
>
> Just for info, the output for "ps aux | grep freeswit" when the
> problem happen:
>
> 0 0.0 0.0 0 0 ? Z< Oct07 0:00 \_ [freeswitch]
> <defunct>
>
> root 11741 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 11755 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 11756 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 11773 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 11803 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 11804 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 11838 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 12027 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 12194 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 12195 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 12232 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 13966 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 14562 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 14563 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 14564 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 14586 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 14590 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 14630 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 14652 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 14653 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 14670 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 14801 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 14802 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 16401 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 16792 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 16899 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 16900 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 16909 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 16910 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 16930 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 16931 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17092 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17093 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17128 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17301 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17318 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17319 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17320 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17321 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17341 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17342 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17375 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17376 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17386 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17387 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17407 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17461 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 17462 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 18870 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 18879 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 18905 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 18906 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 19084 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 19085 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 19332 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 19333 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 19334 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 19351 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 19352 0.0 0.0 0 0 ? Z< Oct07 0:00 \_
> [freeswitch] <defunct>
>
> root 24268 0.0 2.2 1259792 739152 ? SN Oct10 0:00 \_
> /usr/bin/freeswitch -ncwait -nonat -scripts /opt/commsmundi/scripts/fs
>
> root 24855 0.0 4.2 1920068 1397272 ? SN Oct23 0:00 \_
> /usr/bin/freeswitch -ncwait -nonat -scripts /opt/commsmundi/scripts/fs
>
>
> On 24/10/2019 20:35, Mike Jerris wrote:
>> Take a look at log with sip trace enabled but this usually happens
>> when we can’t negotiate codecs.
>>
>>> On Oct 24, 2019, at 10:19 AM, António Silva via FreeSWITCH-users
>>> <freeswitch-users at lists.freeswitch.org
>>> <mailto:freeswitch-users at lists.freeswitch.org>> wrote:
>>>
>>>
>>> *From: *António Silva <asilva at wirelessmundi.com
>>> <mailto:asilva at wirelessmundi.com>>
>>> *Subject: **call drop because of no write codec,
>>> incompatible_destination*
>>> *Date: *October 24, 2019 at 9:40:00 AM MDT
>>> *To: *FreeSWITCH Users Help <freeswitch-users at lists.freeswitch.org
>>> <mailto:freeswitch-users at lists.freeswitch.org>>
>>>
>>>
>>> Hi,
>>>
>>> I'm seeing multiple calls drop with incompatible_destination, i try
>>> to call again the same destination and it works fine. it gets me
>>> crazy...
>>>
>>> In logs i see the error, "has no write codec", in the capture i see
>>> the negotiation both sides have codecs, they are correctly configure
>>> in directory.
>>>
>>> what could be causing this? i'm using version 1.8.6
>>>
>>>
>>> Part of the LOG where the error happens:
>>>
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:37.694352
>>> [ALERT] switch_core_state_machine.c:701
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 session thread sleep
>>> state: CS_CONSUME_MEDIA!
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.794408
>>> [ALERT] switch_core_session.c:1130 Send signal
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 [BREAK]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.794408
>>> [ALERT] switch_core_session.c:1130 Send signal
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 [BREAK]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.794408
>>> [ALERT] switch_core_state_machine.c:705
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 session thread wake
>>> state: CS_CONSUME_MEDIA!
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.814367
>>> [ALERT] switch_core_media.c:486 Looking for zrtp-hash
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.814367
>>> [ALERT] switch_core_media.c:439 Deciding whether to pass zrtp-hash
>>> between legs
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.814367
>>> [ALERT] switch_core_media.c:441 CF_ZRTP_PASSTHRU_REQ not set, so not
>>> propagating zrtp-hash
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.834519
>>> [DEBUG] sofia.c:7325 Channel
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 entering state
>>> [completing][200]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.834519
>>> [DEBUG] sofia.c:7335 Remote SDP:
>>> f39e569f-5184-481a-9f67-6185367e2829 v=0
>>> f39e569f-5184-481a-9f67-6185367e2829 o=11 5008 38 IN IP4 192.168.100.11
>>> f39e569f-5184-481a-9f67-6185367e2829 s=Mapping
>>> f39e569f-5184-481a-9f67-6185367e2829 c=IN IP4 192.168.100.11
>>> f39e569f-5184-481a-9f67-6185367e2829 t=0 0
>>> f39e569f-5184-481a-9f67-6185367e2829 m=audio 5008 RTP/AVP 0 101
>>> f39e569f-5184-481a-9f67-6185367e2829 a=rtpmap:0 PCMU/8000
>>> f39e569f-5184-481a-9f67-6185367e2829 a=rtpmap:101 telephone-event/8000
>>> f39e569f-5184-481a-9f67-6185367e2829 a=fmtp:101 0-16
>>> f39e569f-5184-481a-9f67-6185367e2829 a=ptime:20
>>> f39e569f-5184-481a-9f67-6185367e2829
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.834519
>>> [NOTICE] sofia.c:7338 Pre-Answer
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112!
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.934371
>>> [ALERT] switch_core_session.c:2662
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 Send KeyFrame
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.934371
>>> [DEBUG] switch_core_session.c:2825 EXECUTE [depth=1]
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112
>>> lua(execute_on_ring_b.lua)
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.934371
>>> [ALERT] switch_core_session.c:2889
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 receive message
>>> [APPLICATION_EXEC]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.934371
>>> [ALERT] switch_core_session.c:1047 Send signal
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 [BREAK]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.954358
>>> [ALERT] switch_core_session.c:1047 Send signal
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 [BREAK]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:41.954358
>>> [ALERT] switch_ivr_originate.c:4136
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 receive message
>>> [AUDIO_SYNC]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.034370
>>> [DEBUG] switch_cpp.cpp:1187
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 destroy/unlink
>>> session from object
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.034370
>>> [ALERT] switch_core_session.c:2905
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 receive message
>>> [APPLICATION_EXEC_COMPLETE]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.034370
>>> [DEBUG] switch_channel.c:3537
>>> (sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112) Callstate Change
>>> RINGING -> EARLY
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.094512
>>> [ALERT] sofia.c:7338 sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112
>>> receive message [PROGRESS_EVENT]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.094512
>>> [ALERT] switch_core_media.c:486 Looking for zrtp-hash
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.094512
>>> [ALERT] switch_core_media.c:439 Deciding whether to pass zrtp-hash
>>> between legs
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.094512
>>> [ALERT] switch_core_media.c:441 CF_ZRTP_PASSTHRU_REQ not set, so not
>>> propagating zrtp-hash
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.094512
>>> [ALERT] switch_ivr_bridge.c:1650
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 receive message
>>> [AUDIO_SYNC]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.094512
>>> [ALERT] switch_core_state_machine.c:701
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 session thread sleep
>>> state: CS_CONSUME_MEDIA!
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.094512
>>> [ALERT] switch_ivr_bridge.c:1751
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 receive message [BRIDGE]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.094512
>>> [ALERT] switch_core_session.c:981 Send signal
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 [BREAK]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.094512
>>> [DEBUG] switch_ivr_bridge.c:1795
>>> (sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112) State Change
>>> CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.094512
>>> [ALERT] switch_core_session.c:1480 Send signal
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 [BREAK]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.114382
>>> [ALERT] switch_core_state_machine.c:705
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 session thread wake
>>> state: CS_CONSUME_MEDIA!
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.114382
>>> [DEBUG] switch_core_state_machine.c:584
>>> (sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112) Running State
>>> Change CS_EXCHANGE_MEDIA (Cur 242 Tot 835614)
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.114382
>>> [DEBUG] switch_core_state_machine.c:653
>>> (sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112) State EXCHANGE_MEDIA
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.114382
>>> [ALERT] switch_core_state_machine.c:653
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 Send KeyFrame
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.114382
>>> [DEBUG] mod_sofia.c:657 SOFIA EXCHANGE_MEDIA
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.134357
>>> [ERR] switch_core_media.c:15507
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 has no write codec.
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.134357
>>> [NOTICE] switch_core_media.c:15508 Hangup
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 [CS_EXCHANGE_MEDIA]
>>> [INCOMPATIBLE_DESTINATION]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.134357
>>> [ALERT] switch_channel.c:3346 Send signal
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 [KILL]
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.134357
>>> [DEBUG] mod_hash.c:297 Usage for
>>> total_account:11 at clinicalluch.daratel.com
>>> <mailto:11 at clinicalluch.daratel.com> is now 0
>>> f39e569f-5184-481a-9f67-6185367e2829 2019-10-21 11:50:42.134357
>>> [ALERT] switch_core_session.c:1480 Send signal
>>> sofia/1-perfil-fija/sip:11 at 131.179.185.131:5112 [BREAK]
>>>
>>>
>>>
>>> --
>>> Saludos / Regards / Cumprimentos
>>> António Silva
>>>
>>>
>>>
>>>
>>> _________________________________________________________________________
>>>
>>> The FreeSWITCH project is sponsored by SignalWire https://signalwire.com
>>> Enhance your FreeSWITCH install with disruptive priced SMS and PSTN
>>> services.
>>> Build your next product on our scalable cloud platform.
>>>
>>> Join our online community to chat in real time
>>> https://signalwire.community
>>>
>>> Professional FreeSWITCH Services
>>> sales at freeswitch.com <mailto:sales at freeswitch.com>
>>> https://freeswitch.com
>>>
>>> Official FreeSWITCH Sites
>>> https://freeswitch.com/oss
>>> https://freeswitch.org/confluence
>>> https://cluecon.com
>>>
>>> FreeSWITCH-users mailing list
>>> FreeSWITCH-users at lists.freeswitch.org
>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>>> https://freeswitch.com
>>
> --
> Saludos / Regards / Cumprimentos
> António Silva
--
Saludos / Regards / Cumprimentos
António Silva
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20191126/36cdab13/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Screenshot 2019-11-26 at 17.43.51.png
Type: image/png
Size: 42399 bytes
Desc: not available
URL: <http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20191126/36cdab13/attachment-0001.png>
More information about the FreeSWITCH-users
mailing list