[Freeswitch-users] proxy_media possibly broken? "INCOMPATIBLE_DESTINATION"

Fri Feb 7 00:15:41 MSK 2014

We are trying to relay a fax from one T.38 compatible device to another.
At an early stage, while we are still in PCMA, we receive a
[INCOMPATIBLE_DESTINATION]

This wonders, as Freeswitch should not be really involved in Codec
negociation with the endpoints.

In the logs below I can see, that DTMF  SDP lines are handled as soon as
early media is received from the target endpoint (Asterisk):
   2014-02-06 21:46:26.309091 [DEBUG] switch_core_media.c:3085 Set
telephone-event payload to 101
   2014-02-06 21:46:26.309091 [DEBUG] switch_core_media.c:3382 Set 2833
dtmf send payload to 101

And then there is the INCOMPATIBLE_DESTINATION
  nua.c:879 nua_respond() nua: nua_respond: entering   
   nua_stack.c:529 nua_signal() nua(0x1645df0): sent signal r_respond 
  2014-02-06 21:46:26.309091 [NOTICE] sofia.c:6051 Hangup
sofia/external/49712345 at 30.30.30.30 [CS_CONSUME_MEDIA]
[INCOMPATIBLE_DESTINATION]
   nua_stack.c:573 nua_stack_signal() nua(0x1645df0): recv signal
r_respond 488 Not Acceptable Here
  nua_stack.c:271 nua_stack_event() nua(0x1645df0): event i_error 500
Responding to a Non-Existing Request

So my question is: Is proxy-media broken here? Do I need another
(updated Freeswitch) where this is already solved?

Freeswitch is from GIT mid dec 2013.

The dialplan is (in short) as follows
       <action data="proxy_media=true" application="set" />
       <action data="sofia/gateway/provider/49712345 at 30.30.30.30"
application="bridge" />

SDP are as follows
Sender
v=0
o=FreeSWITCH 1391701261 1391701262 IN IP4 10.10.10.10
s=FreeSWITCH
c=IN IP4 10.10.10.10
t=0 0
m=audio 12816 RTP/AVP 8 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

Freeswitch SDP
v=0
o=FreeSWITCH 0325869010 0325869011 IN IP4 20.20.20.20
s=FreeSWITCH
c=IN IP4 20.20.20.20
t=0 0
m=audio 19068 RTP/AVP 8 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

Receiver's SDP
v=0
o=root 458337462 458337462 IN IP4 30.30.30.31
s=Asterisk PBX 11.0.1
c=IN IP4 30.30.30.31
t=0 0
m=audio 10262 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20

================= Freeswitch LOG ====================================
recv 868 bytes from udp/[30.30.30.30]:5060 at 20:46:26.309161:
   ------------------------------------------------------------------------
   SIP/2.0 183 Session Progress
   Via: SIP/2.0/UDP
20.20.20.20:5080;received=20.20.20.20;rport=5080;branch=z9hG4bKXQeZgU1337FFe
   Record-Route: <sip:30.30.30.30;lr>
   From: "Telefaks" <sip:49691234567 at 20.20.20.20>;tag=myacymU8arjje
   To: <sip:49712345 at 30.30.30.30>;tag=as25c99f07
   Call-ID: 967f3f6c-0a12-1232-a6a1-439bc1c9be81
   CSeq: 55523729 INVITE
   Server: Asterisk PBX 11.0.1
   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY,
INFO, PUBLISH
   Supported: replaces, timer
   Contact: <sip:49712345 at 30.30.30.31:5060>
   Content-Type: application/sdp
   Content-Length: 264

   v=0
   o=root 2049304398 2049304398 IN IP4 30.30.30.31
   s=Asterisk PBX 11.0.1
   c=IN IP4 30.30.30.31
   t=0 0
   m=audio 18798 RTP/AVP 8 101
   a=rtpmap:8 PCMA/8000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=silenceSupp:off - - - -
   a=ptime:20
   a=sendrecv
   ------------------------------------------------------------------------
tport.c:3028 tport_deliver() tport_deliver(0x16d4960): msg
0x7f5f5802d0f0 (868 bytes) from udp/30.30.30.30:5080/sip next=(nil)
nta.c:3221 agent_recv_response() nta: received 183 Session Progress for
INVITE (55523729)
nta.c:3284 agent_recv_response() nta: 183 Session Progress is going to a
transaction
tport.c:4227 tport_release() tport_release(0x16d4960): 0x7f5f5001a6e0 by
0x7f5f5811ced0 with 0x7f5f5802d0f0 (preliminary)
soa.c:1171 soa_set_remote_sdp()
soa_set_remote_sdp(static::0x7f5f6020dea0, (nil), 0x7f5f58123d6c, 264)
called
soa.c:1595 soa_process_answer()
soa_process_answer(static::0x7f5f6020dea0) called
soa_static.c:1137 offer_answer_step()
soa_static_offer_answer_action(0x7f5f6020dea0, soa_process_answer): called
soa_static.c:1020 soa_sdp_mode_set() soa_sdp_mode_set(0x7f5f5001adb0,
0x7f5f581285e0, ""): called
soa_static.c:1283 offer_answer_step() soa_static(0x7f5f6020dea0,
soa_process_answer): upgrade codecs with remote description
soa.c:1730 soa_activate() soa_activate(static::0x7f5f6020dea0, (nil)) called
nua_session.c:988 nua_session_client_response() nua(0x1645df0): INVITE:
processed SDP answer in 183 Session Progress
nua_stack.c:271 nua_stack_event() nua(0x1645df0): event r_invite 183
Session Progress
nua_session.c:4137 signal_call_state_change() nua(0x1645df0): call state
changed: calling -> proceeding, received answer
soa.c:1098 soa_get_remote_sdp()
soa_get_remote_sdp(static::0x7f5f6020dea0, [0x7f5f65afb2f8],
[0x7f5f65afb2f0], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x7f5f6020dea0, ...)
called
nua_stack.c:271 nua_stack_event() nua(0x1645df0): event i_state 183
Session Progress
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2014-02-06 21:46:26.309091 [DEBUG] switch_core_session.c:1048 Send
signal sofia/external/49712345 at 30.30.30.30 [BREAK]
2014-02-06 21:46:26.309091 [ALERT] switch_core_state_machine.c:585
sofia/external/49712345 at 30.30.30.30 session thread wake state:
CS_CONSUME_MEDIA!
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2014-02-06 21:46:26.309091 [DEBUG] switch_core_session.c:1048 Send
signal sofia/external/49712345 at 30.30.30.30 [BREAK]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2014-02-06 21:46:26.309091 [ALERT] switch_core_media.c:286 Looking for
zrtp-hash
2014-02-06 21:46:26.309091 [ALERT] switch_core_media.c:241 Deciding
whether to pass zrtp-hash between legs
2014-02-06 21:46:26.309091 [ALERT] switch_core_media.c:243
CF_ZRTP_PASSTHRU_REQ not set, so not propagating zrtp-hash
2014-02-06 21:46:26.309091 [ALERT] sofia.c:983
sofia/external/49712345 at 30.30.30.30 Same Callee ID "Outbound Call"
<49712345>
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2014-02-06 21:46:26.309091 [DEBUG] sofia.c:5889 Channel
sofia/external/49712345 at 30.30.30.30 entering state [proceeding][183]
2014-02-06 21:46:26.309091 [DEBUG] sofia.c:5899 Remote SDP:
v=0
o=root 2049304398 2049304398 IN IP4 30.30.30.31
s=Asterisk PBX 11.0.1
c=IN IP4 30.30.30.31
t=0 0
m=audio 18798 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20

2014-02-06 21:46:26.309091 [ALERT] switch_core_media.c:286 Looking for
zrtp-hash
2014-02-06 21:46:26.309091 [ALERT] switch_core_media.c:241 Deciding
whether to pass zrtp-hash between legs
2014-02-06 21:46:26.309091 [ALERT] switch_core_media.c:243
CF_ZRTP_PASSTHRU_REQ not set, so not propagating zrtp-hash
2014-02-06 21:46:26.309091 [DEBUG] switch_core_media.c:3085 Set
telephone-event payload to 101
2014-02-06 21:46:26.309091 [DEBUG] switch_core_media.c:3382 Set 2833
dtmf send payload to 101
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:529 nua_signal() nua(0x1645df0): sent signal r_respond
2014-02-06 21:46:26.309091 [NOTICE] sofia.c:6051 Hangup
sofia/external/49712345 at 30.30.30.30 [CS_CONSUME_MEDIA]
[INCOMPATIBLE_DESTINATION]
nua_stack.c:573 nua_stack_signal() nua(0x1645df0): recv signal r_respond
488 Not Acceptable Here
nua_stack.c:271 nua_stack_event() nua(0x1645df0): event i_error 500
Responding to a Non-Existing Request
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering

-- 
With kind regards
Peter Steinbach 