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/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>;tag=DFejDg1B59y9r
To: <sip:385914392122@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>;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>;tag=DFejDg1B59y9r
To: <sip:385914392122@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>;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>;tag=DFejDg1B59y9r
To: <sip:385914392122@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/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>;tag=DFejDg1B59y9r
To: <sip:385914392122@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>;tag=C4B0BE6C-1B8
To: <sip:38518880050@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>;tag=C4B0BE6C-1B8
To: <sip:38518880050@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 .. :)