hello guys, i configured FS HA and looks like its trying to recover the call .. but the re-INVITE fails due to "wrong/missed" codec capability. freeswitch@internal> freeswitch@internal> sofia profile external siptrace on Enabled sip debugging on external freeswitch@internal> sofia profile internal siptrace on Enabled sip debugging on internal freeswitch@internal> freeswitch@internal> freeswitch@internal> freeswitch@internal> sofia recover Recovered 1 call(s) 2011-01-24 21:32:31.667404 [CRIT] switch_odbc.c:205 The sql server is not responding for DSN COREFSdrv [STATE: HY000 CODE 7 ERROR: [unixODBC]Unknown error; FATAL: terminating connection due to administrator command ][176] freeswitch@internal> 2011-01-24 21:32:31.667404 [INFO] switch_odbc.c:210 The connection has been re-established 2011-01-24 21:32:32.726402 [NOTICE] switch_channel.c:669 New Channel sofia/external/385914392122@195.88.212.39[808b0a98-8928-4ca2-a320-8e026ba94018] *2011-01-24 21:32:32.726402 [DEBUG] sofia_glue.c:2354 Set Codec sofia/external/385914392122@195.88.212.39 PCMA/8000 20 ms 160 samples* 2011-01-24 21:32:32.726402 [DEBUG] sofia_glue.c:2594 AUDIO RTP [sofia/external/385914392122@195.88.212.39] 195.88.212.30 port 20092 -> 195.88.212.39 port 17750 codec: 8 ms: 20 2011-01-24 21:32:32.726402 [DEBUG] switch_rtp.c:1182 Starting timer [soft] 160 bytes per 20ms 2011-01-24 21:32:32.728288 [DEBUG] sofia_glue.c:2774 Set 2833 dtmf send payload to 101 2011-01-24 21:32:32.728288 [DEBUG] sofia_glue.c:2779 Set 2833 dtmf receive payload to 101 2011-01-24 21:32:32.728288 [DEBUG] sofia_glue.c:2790 Set comfort noise payload to 13 2011-01-24 21:32:32.779414 [DEBUG] sofia_glue.c:4246 (sofia/external/ 385914392122@195.88.212.39) State Change CS_NEW -> CS_INIT 2011-01-24 21:32:32.779414 [DEBUG] switch_core_session.c:1021 Send signal sofia/external/385914392122@195.88.212.39 [BREAK] 2011-01-24 21:32:32.779414 [NOTICE] sofia_glue.c:4249 Resurrecting fallen channel sofia/external/385914392122@195.88.212.39 2011-01-24 21:32:32.780381 [DEBUG] switch_core_state_machine.c:314 (sofia/external/385914392122@195.88.212.39) Running State Change CS_INIT 2011-01-24 21:32:32.780381 [DEBUG] switch_core_state_machine.c:338 (sofia/external/385914392122@195.88.212.39) State INIT 2011-01-24 21:32:32.780381 [DEBUG] mod_sofia.c:83 sofia/external/ 385914392122@195.88.212.39 SOFIA INIT 2011-01-24 21:32:32.780381 [DEBUG] mod_sofia.c:114 (sofia/external/ 385914392122@195.88.212.39) State Change CS_INIT -> CS_EXECUTE 2011-01-24 21:32:32.780381 [DEBUG] switch_core_session.c:1021 Send signal sofia/external/385914392122@195.88.212.39 [BREAK] 2011-01-24 21:32:32.780381 [DEBUG] switch_core_state_machine.c:338 (sofia/external/385914392122@195.88.212.39) State INIT going to sleep 2011-01-24 21:32:32.780381 [DEBUG] switch_core_state_machine.c:314 (sofia/external/385914392122@195.88.212.39) Running State Change CS_EXECUTE 2011-01-24 21:32:32.780381 [DEBUG] switch_core_state_machine.c:348 (sofia/external/385914392122@195.88.212.39) State EXECUTE 2011-01-24 21:32:32.780381 [DEBUG] mod_sofia.c:226 sofia/external/ 385914392122@195.88.212.39 SOFIA EXECUTE 2011-01-24 21:32:32.780381 [DEBUG] switch_core_state_machine.c:157 sofia/external/385914392122@195.88.212.39 Standard EXECUTE EXECUTE sofia/external/385914392122@195.88.212.39 set(playback_delimiter=!) send 1029 bytes to udp/[195.88.212.39]:62342 at 20:32:32.781241: ------------------------------------------------------------------------ INVITE sip:385914392122@195.88.212.39 <sip%3A385914392122@195.88.212.39>SIP/2.0 Via: SIP/2.0/UDP 195.88.212.30:5080;rport;branch=z9hG4bKKDX31Z2Q71B3j Route: <sip:385914392122@195.88.212.39:62342;lr> Max-Forwards: 69 From: <sip:38518880050@195.88.212.30 <sip%3A38518880050@195.88.212.30>
;tag=DFejDg1B59y9r To: <sip:385914392122@195.88.212.39 <sip%3A385914392122@195.88.212.39> ;tag=C4B0BE6C-1B8 Call-ID: 1785B58B-272611E0-8909D88B-B59C2BD1@195.88.212.39 CSeq: 7614512 INVITE Contact: <sip:385914392122@195.88.212.30:5080> User-Agent: FreeSWITCH-mod_sofia/1.0.6-svn-exported Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY Supported: timer, precondition, path, replaces Allow-Events: talk, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 168 X-FS-Support: update_display Remote-Party-ID: "38518880050" <sip:38518880050@195.88.212.30<sip%3A38518880050@195.88.212.30> ;party=calling;screen=yes;privacy=off
v=0 o=FreeSWITCH 1295881060 1295881062 IN IP4 195.88.212.30 s=FreeSWITCH c=IN IP4 195.88.212.30 t=0 0* m=audio 20092 RTP/AVP 0 13* * a=rtpmap:13 CN/8000* a=ptime:20 ------------------------------------------------------------------------ 2011-01-24 21:32:32.781430 [DEBUG] sofia.c:4153 Channel sofia/external/ 385914392122@195.88.212.39 entering state [calling][0] recv 496 bytes from udp/[195.88.212.39]:5060 at 20:32:32.784077: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 195.88.212.30:5080;rport;branch=z9hG4bKKDX31Z2Q71B3j From: <sip:38518880050@195.88.212.30 <sip%3A38518880050@195.88.212.30>
;tag=DFejDg1B59y9r To: <sip:385914392122@195.88.212.39 <sip%3A385914392122@195.88.212.39> ;tag=C4B0BE6C-1B8 Date: Mon, 24 Jan 2011 19:22:34 GMT Call-ID: 1785B58B-272611E0-8909D88B-B59C2BD1@195.88.212.39 Server: Cisco-SIPGateway/IOS-12.x CSeq: 7614512 INVITE Allow-Events: telephone-event Remote-Party-ID: <sip:385914392122@195.88.212.39<sip%3A385914392122@195.88.212.39> ;party=called;screen=yes;privacy=off Content-Length: 0
------------------------------------------------------------------------ recv 376 bytes from udp/[195.88.212.39]:5060 at 20:32:32.784195: ------------------------------------------------------------------------ SIP/2.0 488 Not Acceptable Media Via: SIP/2.0/UDP 195.88.212.30:5080;rport;branch=z9hG4bKKDX31Z2Q71B3j From: <sip:38518880050@195.88.212.30 <sip%3A38518880050@195.88.212.30>
;tag=DFejDg1B59y9r To: <sip:385914392122@195.88.212.39 <sip%3A385914392122@195.88.212.39> ;tag=C4B0BE6C-1B8 Call-ID: 1785B58B-272611E0-8909D88B-B59C2BD1@195.88.212.39 Warning: 304 195.88.212.39 "Media Type(s) Unavailable" CSeq: 7614512 INVITE Content-Length: 0
------------------------------------------------------------------------ send 395 bytes to udp/[195.88.212.39]:62342 at 20:32:32.784303: ------------------------------------------------------------------------ ACK sip:385914392122@195.88.212.39 <sip%3A385914392122@195.88.212.39>SIP/2.0 Via: SIP/2.0/UDP 195.88.212.30:5080;rport;branch=z9hG4bKKDX31Z2Q71B3j Route: <sip:385914392122@195.88.212.39:62342;lr> Max-Forwards: 69 From: <sip:38518880050@195.88.212.30 <sip%3A38518880050@195.88.212.30>
;tag=DFejDg1B59y9r To: <sip:385914392122@195.88.212.39 <sip%3A385914392122@195.88.212.39> ;tag=C4B0BE6C-1B8 Call-ID: 1785B58B-272611E0-8909D88B-B59C2BD1@195.88.212.39 CSeq: 7614512 ACK Content-Length: 0
------------------------------------------------------------------------ 2011-01-24 21:32:32.784397 [DEBUG] sofia.c:4153 Channel sofia/external/ 385914392122@195.88.212.39 entering state [terminated][488] 2011-01-24 21:32:32.784397 [NOTICE] sofia.c:4789 Hangup sofia/external/ 385914392122@195.88.212.39 [CS_EXECUTE] [INCOMPATIBLE_DESTINATION] 2011-01-24 21:32:32.784397 [DEBUG] switch_channel.c:2102 Send signal sofia/external/385914392122@195.88.212.39 [KILL] 2011-01-24 21:32:32.784397 [DEBUG] switch_core_session.c:1021 Send signal sofia/external/385914392122@195.88.212.39 [BREAK] 2011-01-24 21:32:32.852411 [DEBUG] mod_dptools.c:816 sofia/external/ 385914392122@195.88.212.39 SET [playback_delimiter]=[!] 2011-01-24 21:32:32.853505 [DEBUG] switch_core_state_machine.c:348 (sofia/external/385914392122@195.88.212.39) State EXECUTE going to sleep 2011-01-24 21:32:32.853505 [DEBUG] switch_core_state_machine.c:314 (sofia/external/385914392122@195.88.212.39) Running State Change CS_HANGUP 2011-01-24 21:32:32.853505 [DEBUG] switch_core_state_machine.c:499 (sofia/external/385914392122@195.88.212.39) State HANGUP 2011-01-24 21:32:32.861414 [DEBUG] mod_sofia.c:408 sofia/external/ 385914392122@195.88.212.39 Overriding SIP cause 488 with 488 from the other leg 2011-01-24 21:32:32.861414 [DEBUG] mod_sofia.c:414 Channel sofia/external/ 385914392122@195.88.212.39 hanging up, cause: INCOMPATIBLE_DESTINATION 2011-01-24 21:32:32.863454 [DEBUG] switch_core_state_machine.c:46 sofia/external/385914392122@195.88.212.39 Standard HANGUP, cause: INCOMPATIBLE_DESTINATION 2011-01-24 21:32:32.863454 [DEBUG] switch_core_state_machine.c:499 (sofia/external/385914392122@195.88.212.39) State HANGUP going to sleep 2011-01-24 21:32:32.863454 [DEBUG] switch_core_state_machine.c:333 (sofia/external/385914392122@195.88.212.39) State Change CS_HANGUP -> CS_REPORTING 2011-01-24 21:32:32.863454 [DEBUG] switch_core_session.c:1021 Send signal sofia/external/385914392122@195.88.212.39 [BREAK] 2011-01-24 21:32:32.863454 [DEBUG] switch_core_state_machine.c:314 (sofia/external/385914392122@195.88.212.39) Running State Change CS_REPORTING 2011-01-24 21:32:32.863454 [DEBUG] switch_core_state_machine.c:590 (sofia/external/385914392122@195.88.212.39) State REPORTING 2011-01-24 21:32:32.864328 [DEBUG] switch_core_state_machine.c:53 sofia/external/385914392122@195.88.212.39 Standard REPORTING, cause: INCOMPATIBLE_DESTINATION 2011-01-24 21:32:32.864328 [DEBUG] switch_core_state_machine.c:590 (sofia/external/385914392122@195.88.212.39) State REPORTING going to sleep 2011-01-24 21:32:32.864328 [DEBUG] switch_core_state_machine.c:327 (sofia/external/385914392122@195.88.212.39) State Change CS_REPORTING -> CS_DESTROY 2011-01-24 21:32:32.864328 [DEBUG] switch_core_session.c:1021 Send signal sofia/external/385914392122@195.88.212.39 [BREAK] 2011-01-24 21:32:32.864328 [DEBUG] switch_core_session.c:1164 Session 1 (sofia/external/385914392122@195.88.212.39) Locked, Waiting on external entities 2011-01-24 21:32:32.864328 [NOTICE] switch_core_session.c:1182 Session 1 (sofia/external/385914392122@195.88.212.39) Ended 2011-01-24 21:32:32.864328 [NOTICE] switch_core_session.c:1184 Close Channel sofia/external/385914392122@195.88.212.39 [CS_DESTROY] 2011-01-24 21:32:32.864328 [DEBUG] switch_core_state_machine.c:428 (sofia/external/385914392122@195.88.212.39) Running State Change CS_DESTROY 2011-01-24 21:32:32.864328 [DEBUG] switch_core_state_machine.c:439 (sofia/external/385914392122@195.88.212.39) State DESTROY 2011-01-24 21:32:32.864328 [DEBUG] mod_sofia.c:341 sofia/external/ 385914392122@195.88.212.39 SOFIA DESTROY 2011-01-24 21:32:32.864328 [DEBUG] switch_core_state_machine.c:60 sofia/external/385914392122@195.88.212.39 Standard DESTROY 2011-01-24 21:32:32.864328 [DEBUG] switch_core_state_machine.c:439 (sofia/external/385914392122@195.88.212.39) State DESTROY going to sleep freeswitch@internal> freeswitch@internal> freeswitch@internal> 2011-01-24 21:32:51.813359 [CRIT] switch_odbc.c:205 The sql server is not responding for DSN COREFSdrv [STATE: HY000 CODE 7 ERROR: [unixODBC]Unknown error; FATAL: terminating connection due to administrator command ][176] 2011-01-24 21:32:51.813359 [INFO] switch_odbc.c:210 The connection has been re-established 2011-01-24 21:32:52.810408 [CRIT] switch_odbc.c:205 The sql server is not responding for DSN COREFSdrv [STATE: HY000 CODE 7 ERROR: [unixODBC]Unknown error; FATAL: terminating connection due to administrator command ][176] 2011-01-24 21:32:52.810408 [INFO] switch_odbc.c:210 The connection has been re-established 2011-01-24 21:32:53.817405 [CRIT] switch_odbc.c:205 The sql server is not responding for DSN COREFSdrv [STATE: HY000 CODE 7 ERROR: [unixODBC]Unknown error; FATAL: terminating connection due to administrator command ][176] 2011-01-24 21:32:53.817405 [INFO] switch_odbc.c:210 The connection has been re-established recv 432 bytes from udp/[195.88.212.39]:62342 at 20:33:06.045642: ------------------------------------------------------------------------ BYE sip:385914392122@195.88.212.30:5080 SIP/2.0 Via: SIP/2.0/UDP 195.88.212.39:5060;branch=z9hG4bK240FA From: <sip:385914392122@195.88.212.39 <sip%3A385914392122@195.88.212.39>
;tag=C4B0BE6C-1B8 To: <sip:38518880050@195.88.212.30 <sip%3A38518880050@195.88.212.30> ;tag=DFejDg1B59y9r Date: Mon, 24 Jan 2011 19:22:34 GMT Call-ID: 1785B58B-272611E0-8909D88B-B59C2BD1@195.88.212.39 User-Agent: Cisco-SIPGateway/IOS-12.x Max-Forwards: 70 Timestamp: 1295896987 CSeq: 102 BYE Content-Length: 0
------------------------------------------------------------------------ send 522 bytes to udp/[195.88.212.39]:5060 at 20:33:06.045858: ------------------------------------------------------------------------ SIP/2.0 481 Call Does Not Exist Via: SIP/2.0/UDP 195.88.212.39:5060;branch=z9hG4bK240FA From: <sip:385914392122@195.88.212.39 <sip%3A385914392122@195.88.212.39>
;tag=C4B0BE6C-1B8 To: <sip:38518880050@195.88.212.30 <sip%3A38518880050@195.88.212.30> ;tag=DFejDg1B59y9r Call-ID: 1785B58B-272611E0-8909D88B-B59C2BD1@195.88.212.39 CSeq: 102 BYE Timestamp: 1295896987 0.000191 User-Agent: FreeSWITCH-mod_sofia/1.0.6-svn-exported Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY Supported: timer, precondition, path, replaces Content-Length: 0
------------------------------------------------------------------------ freeswitch@internal> freeswitch@internal> my codec settings in vars.conf <X-PRE-PROCESS cmd="set" data="global_codec_prefs=PCMA,GSM"/> <X-PRE-PROCESS cmd="set" data="outbound_codec_prefs=PCMA,GSM"/> my codec settings in sip_profiles/* <param name="inbound-codec-prefs" value="$${global_codec_prefs}"/> <param name="outbound-codec-prefs" value="$${global_codec_prefs}"/> now, where the is FS picking up the codec list for the re-INVITE after "sofia recover" from the debug: 2011-01-24 21:32:32.726402 [DEBUG] sofia_glue.c:2354 Set Codec sofia/external/385914392122@195.88.212.39 PCMA/8000 20 ms 160 samples i can see sofia knows what codec is being used, but somehow its not sending it in re-INVITE. BTW: yea, i know, i know .. the version is a bit outdated but we can still make it working .. :)