[Freeswitch-users] Overriding 480 with 200 from other leg

[Peder]

I've got a strange issue and I am not 100% sure how to get around it.  

We have a system setup where a user calls in and enters a code.  A perl
script is called that does an http get to find a phone number to dial, it
dials the number, bridges the two and then it records the call.  

Once the code is verified and we have the number, we set two carriers to
call, primary and backup.  This all works great 95%+ of the time.  We do 40k
calls per month and about 50 calls a week run into a scenario that I am not
sure of.   On the ones that don't work, it gets all the way through bridging
the calls with no problem, but when the user hangs up, it doesn't hang up,
it falls to the backup bridge and calls the destination number again our
carrier2, all the while still recording.  We get 3 CDR records, incoming,
call out carrier1 and call out carrier2.

Here is the snippet of the perl script that does the dialing ($bridge and
$backupbridge are the two carriers to call).  If $bridge fails, it goes back
to $backupbridge just fine:

$session->execute("set","continue_on_fail=true");
$session->execute("bridge","sofia/gateway/$bridge/$PhoneNo");
$session->execute("export","nolocal:CARRIER=${backupbridge}");
$session->execute("bridge","sofia/gateway/$backupbridge/$PhoneNo");


Every now and then we see this in the logs "Overriding SIP cause 480 with
200 from the other leg":


2011-01-19 09:24:50.751368 [NOTICE] sofia.c:481 Hangup
sofia/external/1xxxxxx8003 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2011-01-19 09:24:50.753368 [DEBUG] switch_channel.c:2071 Send signal
sofia/external/1xxxxxx8003 [KILL]
2011-01-19 09:24:50.753368 [DEBUG] switch_core_session.c:1018 Send signal
sofia/external/1xxxxxx8003 [BREAK]
2011-01-19 09:24:50.761364 [DEBUG] switch_ivr_bridge.c:478
sofia/external/1xxxxxx8003 ending bridge by request from read function
2011-01-19 09:24:50.761364 [DEBUG] switch_ivr_bridge.c:565 BRIDGE THREAD
DONE [sofia/external/1xxxxxx8003]
2011-01-19 09:24:50.761364 [DEBUG] switch_ivr_bridge.c:585 Send signal
sofia/internal/yyyyyy6168 at 72.249.14.242 [BREAK]
2011-01-19 09:24:50.761364 [DEBUG] switch_core_state_machine.c:351
(sofia/external/1xxxxxx8003) State EXCHANGE_MEDIA going to sleep
2011-01-19 09:24:50.761364 [DEBUG] switch_core_state_machine.c:314
(sofia/external/1xxxxxx8003) Running State Change CS_HANGUP
2011-01-19 09:24:50.761364 [DEBUG] switch_core_state_machine.c:499
(sofia/external/1xxxxxx8003) State HANGUP
2011-01-19 09:24:50.761364 [DEBUG] mod_sofia.c:405
sofia/external/1xxxxxx8003 Overriding SIP cause 480 with 200 from the other
leg
2011-01-19 09:24:50.761364 [DEBUG] mod_sofia.c:411 Channel
sofia/external/1xxxxxx8003 hanging up, cause: NORMAL_CLEARING
2011-01-19 09:24:50.761364 [DEBUG] switch_core_state_machine.c:46
sofia/external/1xxxxxx8003 Standard HANGUP, cause: NORMAL_CLEARING
2011-01-19 09:24:50.761364 [DEBUG] switch_core_state_machine.c:499
(sofia/external/1xxxxxx8003) State HANGUP going to sleep
2011-01-19 09:24:50.761364 [DEBUG] switch_core_state_machine.c:333
(sofia/external/1xxxxxx8003) State Change CS_HANGUP -> CS_REPORTING
2011-01-19 09:24:50.761364 [DEBUG] switch_core_session.c:1018 Send signal
sofia/external/1xxxxxx8003 [BREAK]
2011-01-19 09:24:50.761364 [DEBUG] switch_core_state_machine.c:314
(sofia/external/1xxxxxx8003) Running State Change CS_REPORTING
2011-01-19 09:24:50.761364 [DEBUG] switch_core_state_machine.c:590
(sofia/external/1xxxxxx8003) State REPORTING
2011-01-19 09:24:50.763475 [DEBUG] switch_core_session.c:638 Send signal
sofia/internal/yyyyyy6168 at 72.249.14.242 [BREAK]
2011-01-19 09:24:50.763475 [DEBUG] switch_ivr_bridge.c:565 BRIDGE THREAD
DONE [sofia/internal/yyyyyy6168 at 72.249.14.242]
2011-01-19 09:24:50.763475 [DEBUG] switch_ivr_bridge.c:585 Send signal
sofia/external/1xxxxxx8003 [BREAK]
EXECUTE sofia/internal/yyyyyy6168 at 72.249.14.242
export(nolocal:CARRIER=carrier2)
2011-01-19 09:24:50.766348 [DEBUG] switch_core_state_machine.c:53
sofia/external/1xxxxxx8003 Standard REPORTING, cause: NORMAL_CLEARING
2011-01-19 09:24:50.766348 [DEBUG] switch_core_state_machine.c:590
(sofia/external/1xxxxxx8003) State REPORTING going to sleep
2011-01-19 09:24:50.766348 [DEBUG] switch_core_state_machine.c:327
(sofia/external/1xxxxxx8003) State Change CS_REPORTING -> CS_DESTROY
2011-01-19 09:24:50.766348 [DEBUG] switch_core_session.c:1018 Send signal
sofia/external/1xxxxxx8003 [BREAK]
2011-01-19 09:24:50.766348 [DEBUG] switch_core_session.c:1161 Session 96783
(sofia/external/1xxxxxx8003) Locked, Waiting on external entities
2011-01-19 09:24:50.766348 [NOTICE] switch_core_session.c:1179 Session 96783
(sofia/external/1xxxxxx8003) Ended
2011-01-19 09:24:50.766348 [NOTICE] switch_core_session.c:1181 Close Channel
sofia/external/1xxxxxx8003 [CS_DESTROY]
2011-01-19 09:24:50.766348 [DEBUG] mod_dptools.c:898 EXPORT (REMOTE ONLY)
[CARRIER]=[carrier2]
2011-01-19 09:24:50.766348 [DEBUG] switch_core_state_machine.c:428
(sofia/external/1xxxxxx8003) Running State Change CS_DESTROY
2011-01-19 09:24:50.766348 [DEBUG] switch_core_state_machine.c:439
(sofia/external/1xxxxxx8003) State DESTROY
2011-01-19 09:24:50.766348 [DEBUG] mod_sofia.c:338
sofia/external/1xxxxxx8003 SOFIA DESTROY
EXECUTE sofia/internal/yyyyyy6168 at 72.249.14.242
bridge(sofia/gateway/carrier2/1xxxxxx8003)


I am guessing that carrier1 is sending back a 480, so FS thinks it never
worked and then bridges out carrier2.  Our FS is pretty old, FreeSWITCH
Version 1.0.trunk (17043), but I don't think it is an FS issue, I think it
is just a dialplan issue that I don't know how to resolve.  Any idea how to
stop this from happening?  

Peder