[Freeswitch-users] FreeSWITCH High availability(Normal_temporary_failure problem)

Wed Nov 7 11:03:22 MSK 2012

Hi,

I am trying to achieve high availability in FreeSWITCH using heartbeat and
pacemaker and I am able to switch between the server whenever one of the
servers crashes. But the problem is one server is able to recover the calls
when im invoking sofia recover, but another server is recovering the call
one few times.(Mostly not able to recover).

I have primary and secondary server installed in two different
machines(centos), the FreeSWITCH instances are always running in both the
PCs. I am running heartbeat and pacemaker to monitor the IP or sofia
fail-over. A floating IP is configure in heartbeat to reach the active
server.
I succeeded in switching between the servers whenever IP or FreeSWITCH and
once it reaches the another server it invokes sofia recover to recover the
calls.

Both freeswtich instances are using the same configuration and database is
shared using ODBC connectivity.

Problem is:

Call is made using the primary server, and i did fsctl crash in primary
server cli. Heartbeat resource switches to secondary server and it invokes
"sofia profile internal restart" and "sofia recover". and it recovers the
call. The call gets recovered in 4-5 seconds.

At the same time i will start the freeswitch instance in the primary
server. Now if i crash the secondary server using fsctl crash, the
resources switches to primary server and it invokes "sofia profile internal
restart" and "sofia recover". Also the server sends invite request to the
clients But it ends in NORMAL_TEMPORARY_FAILURE. Wireshark log says Client
is responding with "Invalid CSeq" for the Server's INVITE request. This
happens always with the primary server and very few times primary server is
also able to recover the calls.

I have the same configurations in both the servers
And also i checked by stopping the heartbeat switching, and crashed the
primary server's freeswitch. Then if i start freeswitch again in the same
server and invoking sofia recover will recover the calls without any
problem.

I have also attached the cli logs of primary and secondary servers.
I am not able to identify the exact problem in this, Please help me out in
this problem.

Thanks
Rajkumar
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20121107/b40e2800/attachment-0001.html 
-------------- next part --------------
/* call recovered */

2012-10-31 09:19:22.639229 [NOTICE] switch_channel.c:941 New Channel sofia/internal/3606 at 10.1.3.50 [6a8db0f1-d26d-49a9-9498-093ec5174aae]
2012-10-31 09:19:22.639229 [NOTICE] switch_channel.c:939 Rename Channel sofia/internal/3606 at 10.1.3.50->sofia/internal/3606 at 10.1.3.50 [6a8db0f1-d26d-49a9-9498-093ec5174aae]
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3027 Set Codec sofia/internal/3606 at 10.1.3.50 PCMU/8000 20 ms 160 samples 64000 bits
2012-10-31 09:19:22.639229 [DEBUG] switch_core_codec.c:111 sofia/internal/3606 at 10.1.3.50 Original read codec set to PCMU:0
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3276 AUDIO RTP [sofia/internal/3606 at 10.1.3.50] 10.1.3.50 port 17242 -> 10.1.45.149 port 4000 codec: 0 ms: 20
2012-10-31 09:19:22.639229 [DEBUG] switch_rtp.c:1935 Not using a timer
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3540 Set 2833 dtmf send payload to 101
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3546 Set 2833 dtmf receive payload to 101
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3573 sofia/internal/3606 at 10.1.3.50 Set rtp dtmf delay to 40
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3579 Set comfort noise payload to 13
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:5965 (sofia/internal/3606 at 10.1.3.50) State Change CS_NEW -> CS_INIT
2012-10-31 09:19:22.639229 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/3606 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.639229 [NOTICE] sofia_glue.c:5966 Resurrecting fallen channel sofia/internal/3606 at 10.1.3.50

2012-10-31 09:19:22.639229 [NOTICE] switch_channel.c:941 New Channel sofia/internal/3429 at 10.1.3.50 [b2da4eae-c696-434d-89ee-5ebcd978a668]
2012-10-31 09:19:22.639229 [NOTICE] switch_channel.c:939 Rename Channel sofia/internal/3429 at 10.1.3.50->sofia/internal/3429 at 10.1.3.50 [b2da4eae-c696-434d-89ee-5ebcd978a668]
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3027 Set Codec sofia/internal/3429 at 10.1.3.50 PCMU/8000 20 ms 160 samples 64000 bits
2012-10-31 09:19:22.639229 [DEBUG] switch_core_codec.c:111 sofia/internal/3429 at 10.1.3.50 Original read codec set to PCMU:0
2012-10-31 09:19:22.639229 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/3606 at 10.1.3.50) Running State Change CS_INIT
2012-10-31 09:19:22.639229 [DEBUG] switch_channel.c:1936 (sofia/internal/3606 at 10.1.3.50) Callstate Change DOWN -> ACTIVE
2012-10-31 09:19:22.639229 [DEBUG] switch_core_state_machine.c:424 (sofia/internal/3606 at 10.1.3.50) State INIT
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3276 AUDIO RTP [sofia/internal/3429 at 10.1.3.50] 10.1.3.50 port 25200 -> 10.1.45.148 port 4000 codec: 0 ms: 20
2012-10-31 09:19:22.639229 [DEBUG] mod_sofia.c:85 sofia/internal/3606 at 10.1.3.50 SOFIA INIT
2012-10-31 09:19:22.639229 [DEBUG] switch_rtp.c:1935 Not using a timer
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:2609 Local SDP:
v=0
o=FreeSWITCH 1351638120 1351638122 IN IP4 10.1.3.50
s=FreeSWITCH
c=IN IP4 10.1.3.50
t=0 0
m=audio 17242 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2012-10-31 09:19:22.639229 [DEBUG] mod_sofia.c:119 (sofia/internal/3606 at 10.1.3.50) State Change CS_INIT -> CS_RESET
2012-10-31 09:19:22.639229 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/3606 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.639229 [DEBUG] switch_core_state_machine.c:424 (sofia/internal/3606 at 10.1.3.50) State INIT going to sleep
2012-10-31 09:19:22.639229 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/3606 at 10.1.3.50) Running State Change CS_RESET
2012-10-31 09:19:22.639229 [DEBUG] switch_core_state_machine.c:436 (sofia/internal/3606 at 10.1.3.50) State RESET
2012-10-31 09:19:22.639229 [DEBUG] mod_sofia.c:166 sofia/internal/3606 at 10.1.3.50 SOFIA RESET
2012-10-31 09:19:22.639229 [DEBUG] switch_core_state_machine.c:93 sofia/internal/3606 at 10.1.3.50 Standard RESET
2012-10-31 09:19:22.639229 [DEBUG] switch_core_state_machine.c:436 (sofia/internal/3606 at 10.1.3.50) State RESET going to sleep
2012-10-31 09:19:22.639229 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/3606 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.639229 [DEBUG] sofia.c:6040 Channel sofia/internal/3606 at 10.1.3.50 entering state [calling][0]
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3540 Set 2833 dtmf send payload to 101
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3546 Set 2833 dtmf receive payload to 101
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3573 sofia/internal/3429 at 10.1.3.50 Set rtp dtmf delay to 40
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3579 Set comfort noise payload to 13
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:5965 (sofia/internal/3429 at 10.1.3.50) State Change CS_NEW -> CS_INIT
2012-10-31 09:19:22.639229 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.639229 [NOTICE] sofia_glue.c:5966 Resurrecting fallen channel sofia/internal/3429 at 10.1.3.50
2012-10-31 09:19:22.639229 [NOTICE] switch_channel.c:941 New Channel sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [09de40c0-eba4-44a3-aa4d-d47ec4b2acf0]
2012-10-31 09:19:22.639229 [NOTICE] switch_channel.c:939 Rename Channel sofia/internal/sip:ukytvsci at 10.1.19.195:1292->sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [09de40c0-eba4-44a3-aa4d-d47ec4b2acf0]
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3027 Set Codec sofia/internal/sip:ukytvsci at 10.1.19.195:1292 PCMU/8000 20 ms 160 samples 64000 bits
2012-10-31 09:19:22.639229 [DEBUG] switch_core_codec.c:111 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 Original read codec set to PCMU:0
2012-10-31 09:19:22.639229 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/3429 at 10.1.3.50) Running State Change CS_INIT
2012-10-31 09:19:22.639229 [DEBUG] switch_channel.c:1936 (sofia/internal/3429 at 10.1.3.50) Callstate Change DOWN -> ACTIVE
2012-10-31 09:19:22.639229 [DEBUG] switch_core_state_machine.c:424 (sofia/internal/3429 at 10.1.3.50) State INIT
2012-10-31 09:19:22.639229 [DEBUG] mod_sofia.c:85 sofia/internal/3429 at 10.1.3.50 SOFIA INIT
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3276 AUDIO RTP [sofia/internal/sip:ukytvsci at 10.1.19.195:1292] 10.1.3.50 port 18356 -> 10.1.19.195 port 50000 codec: 0 ms: 20
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:2609 Local SDP:
v=0
o=FreeSWITCH 1351630162 1351630164 IN IP4 10.1.3.50
s=FreeSWITCH
c=IN IP4 10.1.3.50
t=0 0
m=audio 25200 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2012-10-31 09:19:22.639229 [DEBUG] mod_sofia.c:119 (sofia/internal/3429 at 10.1.3.50) State Change CS_INIT -> CS_RESET
2012-10-31 09:19:22.639229 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.639229 [DEBUG] switch_core_state_machine.c:424 (sofia/internal/3429 at 10.1.3.50) State INIT going to sleep
2012-10-31 09:19:22.639229 [DEBUG] switch_rtp.c:1935 Not using a timer
2012-10-31 09:19:22.639229 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/3429 at 10.1.3.50) Running State Change CS_RESET
2012-10-31 09:19:22.639229 [DEBUG] switch_core_state_machine.c:436 (sofia/internal/3429 at 10.1.3.50) State RESET
2012-10-31 09:19:22.639229 [DEBUG] mod_sofia.c:166 sofia/internal/3429 at 10.1.3.50 SOFIA RESET
2012-10-31 09:19:22.639229 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3540 Set 2833 dtmf send payload to 101
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3546 Set 2833 dtmf receive payload to 101
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3573 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 Set rtp dtmf delay to 40
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:3579 Set comfort noise payload to 13
2012-10-31 09:19:22.639229 [DEBUG] sofia_glue.c:5965 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State Change CS_NEW -> CS_INIT
2012-10-31 09:19:22.659361 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.659361 [NOTICE] sofia_glue.c:5966 Resurrecting fallen channel sofia/internal/sip:ukytvsci at 10.1.19.195:1292
2012-10-31 09:19:22.659361 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Running State Change CS_INIT
2012-10-31 09:19:22.659361 [DEBUG] switch_channel.c:1936 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Callstate Change DOWN -> ACTIVE
2012-10-31 09:19:22.659361 [DEBUG] switch_core_state_machine.c:424 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State INIT
2012-10-31 09:19:22.659361 [DEBUG] mod_sofia.c:85 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 SOFIA INIT
2012-10-31 09:19:22.659361 [DEBUG] sofia_glue.c:2609 Local SDP:
v=0
o=FreeSWITCH 1351637006 1351637008 IN IP4 10.1.3.50
s=FreeSWITCH
c=IN IP4 10.1.3.50
t=0 0
m=audio 18356 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2012-10-31 09:19:22.659361 [DEBUG] mod_sofia.c:119 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State Change CS_INIT -> CS_RESET
2012-10-31 09:19:22.659361 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.659361 [DEBUG] switch_core_state_machine.c:424 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State INIT going to sleep
2012-10-31 09:19:22.659361 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Running State Change CS_RESET
2012-10-31 09:19:22.659361 [DEBUG] switch_core_state_machine.c:436 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State RESET
2012-10-31 09:19:22.659361 [DEBUG] mod_sofia.c:166 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 SOFIA RESET
2012-10-31 09:19:22.659361 [DEBUG] switch_core_state_machine.c:93 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 Standard RESET
2012-10-31 09:19:22.659361 [DEBUG] switch_core_state_machine.c:436 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State RESET going to sleep
2012-10-31 09:19:22.659361 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.659361 [DEBUG] sofia.c:6040 Channel sofia/internal/sip:ukytvsci at 10.1.19.195:1292 entering state [calling][0]
2012-10-31 09:19:22.659361 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.659361 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.659361 [DEBUG] sofia.c:6040 Channel sofia/internal/sip:ukytvsci at 10.1.19.195:1292 entering state [completing][200]
2012-10-31 09:19:22.659361 [DEBUG] sofia.c:6051 Remote SDP:
v=0^M
o=- 3560663913 3560663915 IN IP4 10.1.19.195^M
s=Blink 0.2.7 (Windows)^M
c=IN IP4 10.1.19.195^M
t=0 0^M
m=audio 50000 RTP/AVP 0 101^M
a=rtpmap:0 PCMU/8000^M
a=rtpmap:101 telephone-event/8000^M
a=fmtp:101 0-15^M
a=rtcp:50001^M

2012-10-31 09:19:22.659361 [DEBUG] sofia_glue.c:3948 Looking for zrtp-hash
2012-10-31 09:19:22.659361 [DEBUG] sofia_glue.c:3926 Deciding whether to pass zrtp-hash between legs
2012-10-31 09:19:22.659361 [DEBUG] sofia_glue.c:3928 CF_ZRTP_PASSTHRU_REQ not set, so not propagating zrtp-hash
2012-10-31 09:19:22.659361 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.659361 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.659361 [DEBUG] sofia.c:6040 Channel sofia/internal/sip:ukytvsci at 10.1.19.195:1292 entering state [ready][200]
2012-10-31 09:19:22.659361 [DEBUG] sofia_glue.c:3948 Looking for zrtp-hash
2012-10-31 09:19:22.659361 [DEBUG] sofia_glue.c:3926 Deciding whether to pass zrtp-hash between legs
2012-10-31 09:19:22.659361 [DEBUG] sofia_glue.c:3928 CF_ZRTP_PASSTHRU_REQ not set, so not propagating zrtp-hash
2012-10-31 09:19:22.659361 [DEBUG] sofia_glue.c:5044 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2012-10-31 09:19:22.659361 [DEBUG] sofia_glue.c:2961 Already using PCMU
2012-10-31 09:19:22.659361 [DEBUG] sofia_glue.c:5158 Set 2833 dtmf send payload to 101
2012-10-31 09:19:22.679370 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.679370 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.739357 [INFO] switch_channel.c:2776 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 Flipping CID from "Extension 3429" <3429> to "Outbound Call" <ukytvsci>
2012-10-31 09:19:22.739357 [DEBUG] switch_ivr_bridge.c:1672 (sofia/internal/3429 at 10.1.3.50) State Change CS_RESET -> CS_HIBERNATE
2012-10-31 09:19:22.739357 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.739357 [DEBUG] switch_ivr_bridge.c:1674 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State Change CS_RESET -> CS_HIBERNATE
2012-10-31 09:19:22.739357 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.739357 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Running State Change CS_HIBERNATE
2012-10-31 09:19:22.739357 [DEBUG] switch_core_session.c:840 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.739357 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State HIBERNATE
2012-10-31 09:19:22.739357 [DEBUG] mod_sofia.c:222 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 SOFIA HIBERNATE
2012-10-31 09:19:22.739357 [DEBUG] switch_ivr_bridge.c:757 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State Change CS_HIBERNATE -> CS_RESET
2012-10-31 09:19:22.739357 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.739357 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State HIBERNATE going to sleep
2012-10-31 09:19:22.739357 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Running State Change CS_RESET
2012-10-31 09:19:22.739357 [DEBUG] switch_core_state_machine.c:436 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State RESET
2012-10-31 09:19:22.739357 [DEBUG] mod_sofia.c:166 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 SOFIA RESET
2012-10-31 09:19:22.739357 [DEBUG] switch_ivr_bridge.c:742 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 CUSTOM RESET
2012-10-31 09:19:22.739357 [DEBUG] switch_core_state_machine.c:93 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 Standard RESET
2012-10-31 09:19:22.739357 [DEBUG] switch_core_state_machine.c:436 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State RESET going to sleep
2012-10-31 09:19:22.739357 [DEBUG] switch_core_session.c:840 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.739357 [DEBUG] switch_ivr_bridge.c:742 sofia/internal/3429 at 10.1.3.50 CUSTOM RESET
2012-10-31 09:19:22.759770 [DEBUG] switch_core_state_machine.c:436 (sofia/internal/3429 at 10.1.3.50) State RESET going to sleep
2012-10-31 09:19:22.759770 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/3429 at 10.1.3.50) Running State Change CS_HIBERNATE
2012-10-31 09:19:22.759770 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/3429 at 10.1.3.50) State HIBERNATE
2012-10-31 09:19:22.759770 [DEBUG] mod_sofia.c:222 sofia/internal/3429 at 10.1.3.50 SOFIA HIBERNATE
2012-10-31 09:19:22.759770 [DEBUG] switch_ivr_bridge.c:757 (sofia/internal/3429 at 10.1.3.50) State Change CS_HIBERNATE -> CS_RESET
2012-10-31 09:19:22.759770 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.759770 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/3429 at 10.1.3.50) State HIBERNATE going to sleep
2012-10-31 09:19:22.759770 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/3429 at 10.1.3.50) Running State Change CS_RESET
2012-10-31 09:19:22.759770 [DEBUG] switch_core_state_machine.c:436 (sofia/internal/3429 at 10.1.3.50) State RESET
2012-10-31 09:19:22.759770 [DEBUG] mod_sofia.c:166 sofia/internal/3429 at 10.1.3.50 SOFIA RESET
2012-10-31 09:19:22.759770 [DEBUG] switch_ivr_bridge.c:742 sofia/internal/3429 at 10.1.3.50 CUSTOM RESET
2012-10-31 09:19:22.759770 [DEBUG] switch_ivr_bridge.c:749 (sofia/internal/3429 at 10.1.3.50) State Change CS_RESET -> CS_SOFT_EXECUTE
2012-10-31 09:19:22.759770 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.759770 [DEBUG] switch_core_state_machine.c:436 (sofia/internal/3429 at 10.1.3.50) State RESET going to sleep
2012-10-31 09:19:22.759770 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/3429 at 10.1.3.50) Running State Change CS_SOFT_EXECUTE
2012-10-31 09:19:22.759770 [DEBUG] switch_core_state_machine.c:446 (sofia/internal/3429 at 10.1.3.50) State SOFT_EXECUTE
2012-10-31 09:19:22.759770 [DEBUG] mod_sofia.c:652 SOFIA SOFT_EXECUTE
2012-10-31 09:19:22.759770 [DEBUG] switch_ivr_bridge.c:767 sofia/internal/3429 at 10.1.3.50 CUSTOM SOFT_EXECUTE
2012-10-31 09:19:22.759770 [DEBUG] sofia.c:6040 Channel sofia/internal/3429 at 10.1.3.50 entering state [calling][0]
2012-10-31 09:19:22.759770 [DEBUG] sofia.c:6040 Channel sofia/internal/3429 at 10.1.3.50 entering state [completing][200]
2012-10-31 09:19:22.759770 [DEBUG] sofia.c:6051 Remote SDP:
v=0^M
o=- 3560644143 3560644144 IN IP4 10.1.45.148^M
s=pjmedia^M
c=IN IP4 10.1.45.148^M
t=0 0^M
a=X-nat:0^M
m=audio 4000 RTP/AVP 0 101^M
a=rtpmap:0 PCMU/8000^M
a=rtpmap:101 telephone-event/8000^M
a=fmtp:101 0-15^M
a=rtcp:4001 IN IP4 10.1.45.148^M

2012-10-31 09:19:22.759770 [DEBUG] switch_ivr_bridge.c:799 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State Change CS_RESET -> CS_SOFT_EXECUTE
2012-10-31 09:19:22.759770 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.759770 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.759770 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.759770 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Running State Change CS_SOFT_EXECUTE
2012-10-31 09:19:22.759770 [DEBUG] switch_core_state_machine.c:446 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State SOFT_EXECUTE
2012-10-31 09:19:22.759770 [DEBUG] mod_sofia.c:652 SOFIA SOFT_EXECUTE
2012-10-31 09:19:22.759770 [DEBUG] switch_ivr_bridge.c:767 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 CUSTOM SOFT_EXECUTE
2012-10-31 09:19:22.759770 [DEBUG] switch_core_state_machine.c:264 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 Standard SOFT_EXECUTE
2012-10-31 09:19:22.759770 [DEBUG] switch_core_state_machine.c:446 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State SOFT_EXECUTE going to sleep
2012-10-31 09:19:22.779360 [DEBUG] sofia.c:6040 Channel sofia/internal/3429 at 10.1.3.50 entering state [ready][200]
2012-10-31 09:19:22.779360 [DEBUG] sofia_glue.c:3948 Looking for zrtp-hash
2012-10-31 09:19:22.779360 [DEBUG] sofia_glue.c:3926 Deciding whether to pass zrtp-hash between legs
2012-10-31 09:19:22.779360 [DEBUG] sofia_glue.c:3928 CF_ZRTP_PASSTHRU_REQ not set, so not propagating zrtp-hash
2012-10-31 09:19:22.779360 [DEBUG] sofia_glue.c:5044 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2012-10-31 09:19:22.779360 [DEBUG] sofia_glue.c:2961 Already using PCMU
2012-10-31 09:19:22.779360 [DEBUG] sofia_glue.c:5165 Set 2833 dtmf send/recv payload to 101
2012-10-31 09:19:22.779360 [DEBUG] switch_ivr_bridge.c:1257 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State Change CS_SOFT_EXECUTE -> CS_CONSUME_MEDIA
2012-10-31 09:19:22.779360 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.779360 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Running State Change CS_CONSUME_MEDIA
2012-10-31 09:19:22.779360 [DEBUG] switch_core_state_machine.c:452 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State CONSUME_MEDIA
2012-10-31 09:19:22.779360 [DEBUG] switch_ivr_bridge.c:706 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 CUSTOM HOLD
2012-10-31 09:19:22.779360 [DEBUG] switch_core_state_machine.c:452 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State CONSUME_MEDIA going to sleep
2012-10-31 09:19:22.779360 [DEBUG] switch_core_session.c:778 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.779360 [DEBUG] switch_core_session.c:778 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.779360 [DEBUG] switch_ivr_bridge.c:1359 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2012-10-31 09:19:22.779360 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.779360 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Running State Change CS_EXCHANGE_MEDIA
2012-10-31 09:19:22.779360 [DEBUG] switch_core_state_machine.c:443 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State EXCHANGE_MEDIA
2012-10-31 09:19:22.779360 [DEBUG] mod_sofia.c:646 SOFIA EXCHANGE_MEDIA
2012-10-31 09:19:22.779360 [DEBUG] switch_core_session.c:840 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:19:22.779360 [DEBUG] switch_core_session.c:840 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:19:22.779360 [DEBUG] mod_sofia.c:2280 Not sending same id again "3429" <3429>
2012-10-31 09:19:22.779360 [DEBUG] switch_rtp.c:3594 Correct ip/port confirmed.
2012-10-31 09:19:22.779360 [DEBUG] switch_rtp.c:3594 Correct ip/port confirmed.
-------------- next part --------------
/*  call is not recovered */

2012-10-31 09:31:37.495317 [NOTICE] switch_channel.c:941 New Channel sofia/internal/3429 at 10.1.3.50 [b6f8eb4d-19d0-46ee-983d-81175e7f222b]
2012-10-31 09:31:37.495317 [NOTICE] switch_channel.c:939 Rename Channel sofia/internal/3429 at 10.1.3.50->sofia/internal/3429 at 10.1.3.50 [b6f8eb4d-19d0-46ee-983d-81175e7f222b]
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:3027 Set Codec sofia/internal/3429 at 10.1.3.50 PCMU/8000 20 ms 160 samples 64000 bits
2012-10-31 09:31:37.495317 [DEBUG] switch_core_codec.c:111 sofia/internal/3429 at 10.1.3.50 Original read codec set to PCMU:0
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:3276 AUDIO RTP [sofia/internal/3429 at 10.1.3.50] 10.1.3.50 port 25076 -> 10.1.45.148 port 4006 codec: 0 ms: 20
2012-10-31 09:31:37.495317 [DEBUG] switch_rtp.c:1935 Not using a timer
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:3540 Set 2833 dtmf send payload to 101
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:3546 Set 2833 dtmf receive payload to 101
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:3573 sofia/internal/3429 at 10.1.3.50 Set rtp dtmf delay to 40
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:3579 Set comfort noise payload to 13
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:5965 (sofia/internal/3429 at 10.1.3.50) State Change CS_NEW -> CS_INIT
2012-10-31 09:31:37.495317 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:31:37.495317 [NOTICE] sofia_glue.c:5966 Resurrecting fallen channel sofia/internal/3429 at 10.1.3.50
2012-10-31 09:31:37.495317 [NOTICE] switch_channel.c:941 New Channel sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [048fd28b-765f-4444-9eb4-90487d72d191]
2012-10-31 09:31:37.495317 [NOTICE] switch_channel.c:939 Rename Channel sofia/internal/sip:ukytvsci at 10.1.19.195:1292->sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [048fd28b-765f-4444-9eb4-90487d72d191]
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:3027 Set Codec sofia/internal/sip:ukytvsci at 10.1.19.195:1292 PCMU/8000 20 ms 160 samples 64000 bits
2012-10-31 09:31:37.495317 [DEBUG] switch_core_codec.c:111 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 Original read codec set to PCMU:0
2012-10-31 09:31:37.495317 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/3429 at 10.1.3.50) Running State Change CS_INIT
2012-10-31 09:31:37.495317 [DEBUG] switch_channel.c:1936 (sofia/internal/3429 at 10.1.3.50) Callstate Change DOWN -> ACTIVE
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:3276 AUDIO RTP [sofia/internal/sip:ukytvsci at 10.1.19.195:1292] 10.1.3.50 port 26368 -> 10.1.19.195 port 50006 codec: 0 ms: 20
2012-10-31 09:31:37.495317 [DEBUG] switch_core_state_machine.c:424 (sofia/internal/3429 at 10.1.3.50) State INIT
2012-10-31 09:31:37.495317 [DEBUG] mod_sofia.c:85 sofia/internal/3429 at 10.1.3.50 SOFIA INIT
2012-10-31 09:31:37.495317 [DEBUG] switch_rtp.c:1935 Not using a timer
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:2609 Local SDP:
v=0
o=FreeSWITCH 1351631021 1351631023 IN IP4 10.1.3.50
s=FreeSWITCH
c=IN IP4 10.1.3.50
t=0 0
m=audio 25076 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2012-10-31 09:31:37.495317 [DEBUG] mod_sofia.c:119 (sofia/internal/3429 at 10.1.3.50) State Change CS_INIT -> CS_RESET
2012-10-31 09:31:37.495317 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:31:37.495317 [DEBUG] switch_core_state_machine.c:424 (sofia/internal/3429 at 10.1.3.50) State INIT going to sleep
2012-10-31 09:31:37.495317 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/3429 at 10.1.3.50) Running State Change CS_RESET
2012-10-31 09:31:37.495317 [DEBUG] switch_core_state_machine.c:436 (sofia/internal/3429 at 10.1.3.50) State RESET
2012-10-31 09:31:37.495317 [DEBUG] mod_sofia.c:166 sofia/internal/3429 at 10.1.3.50 SOFIA RESET
2012-10-31 09:31:37.495317 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:3540 Set 2833 dtmf send payload to 101
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:3546 Set 2833 dtmf receive payload to 101
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:3573 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 Set rtp dtmf delay to 40
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:3579 Set comfort noise payload to 13
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:5965 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State Change CS_NEW -> CS_INIT
2012-10-31 09:31:37.495317 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:31:37.495317 [NOTICE] sofia_glue.c:5966 Resurrecting fallen channel sofia/internal/sip:ukytvsci at 10.1.19.195:1292
2012-10-31 09:31:37.495317 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Running State Change CS_INIT
2012-10-31 09:31:37.495317 [DEBUG] switch_channel.c:1936 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Callstate Change DOWN -> ACTIVE
2012-10-31 09:31:37.495317 [DEBUG] switch_core_state_machine.c:424 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State INIT
2012-10-31 09:31:37.495317 [DEBUG] mod_sofia.c:85 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 SOFIA INIT
2012-10-31 09:31:37.495317 [DEBUG] sofia_glue.c:2609 Local SDP:
v=0
o=FreeSWITCH 1351629729 1351629731 IN IP4 10.1.3.50
s=FreeSWITCH
c=IN IP4 10.1.3.50
t=0 0
m=audio 26368 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2012-10-31 09:31:37.495317 [DEBUG] mod_sofia.c:119 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State Change CS_INIT -> CS_RESET
2012-10-31 09:31:37.495317 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:31:37.495317 [DEBUG] switch_core_state_machine.c:424 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State INIT going to sleep
2012-10-31 09:31:37.495317 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Running State Change CS_RESET
2012-10-31 09:31:37.495317 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:31:37.495317 [DEBUG] switch_core_state_machine.c:436 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State RESET
2012-10-31 09:31:37.495317 [DEBUG] mod_sofia.c:166 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 SOFIA RESET
2012-10-31 09:31:37.495317 [DEBUG] switch_core_state_machine.c:93 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 Standard RESET
2012-10-31 09:31:37.495317 [DEBUG] switch_core_state_machine.c:436 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State RESET going to sleep
2012-10-31 09:31:37.495317 [DEBUG] sofia.c:6045 Channel sofia/internal/sip:ukytvsci at 10.1.19.195:1292 entering state [calling][0]
2012-10-31 09:31:37.495317 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:31:37.495317 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:31:37.495317 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:31:37.495317 [DEBUG] sofia.c:6045 Channel sofia/internal/sip:ukytvsci at 10.1.19.195:1292 entering state [terminated][500]
2012-10-31 09:31:37.495317 [DEBUG] switch_channel.c:2914 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Callstate Change ACTIVE -> HANGUP
2012-10-31 09:31:37.495317 [NOTICE] sofia.c:6837 Hangup sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [CS_RESET] [NORMAL_TEMPORARY_FAILURE]
2012-10-31 09:31:37.495317 [DEBUG] switch_channel.c:2937 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [KILL]
2012-10-31 09:31:37.495317 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:31:37.495317 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Running State Change CS_HANGUP
2012-10-31 09:31:37.515319 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State HANGUP
2012-10-31 09:31:37.515319 [DEBUG] mod_sofia.c:469 Channel sofia/internal/sip:ukytvsci at 10.1.19.195:1292 hanging up, cause: NORMAL_TEMPORARY_FAILURE
2012-10-31 09:31:37.515319 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:31:37.515319 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:31:37.515319 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:31:37.515319 [DEBUG] switch_core_state_machine.c:47 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2012-10-31 09:31:37.515319 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State HANGUP going to sleep
2012-10-31 09:31:37.515319 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State Change CS_HANGUP -> CS_REPORTING
2012-10-31 09:31:37.515319 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:31:37.515319 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Running State Change CS_REPORTING
2012-10-31 09:31:37.515319 [DEBUG] switch_core_state_machine.c:685 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State REPORTING
2012-10-31 09:31:37.515319 [DEBUG] switch_core_state_machine.c:79 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
2012-10-31 09:31:37.515319 [DEBUG] switch_core_state_machine.c:685 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State REPORTING going to sleep
2012-10-31 09:31:37.515319 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State Change CS_REPORTING -> CS_DESTROY
2012-10-31 09:31:37.515319 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [BREAK]
2012-10-31 09:31:37.515319 [DEBUG] switch_core_session.c:1429 Session 2 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Locked, Waiting on external entities
2012-10-31 09:31:37.595338 [DEBUG] switch_ivr_bridge.c:1685 originatee uuid 048fd28b-765f-4444-9eb4-90487d72d191 is not present
2012-10-31 09:31:37.595338 [DEBUG] switch_core_state_machine.c:93 sofia/internal/3429 at 10.1.3.50 Standard RESET
2012-10-31 09:31:37.595338 [NOTICE] switch_core_session.c:1447 Session 2 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Ended
2012-10-31 09:31:37.595338 [DEBUG] switch_core_state_machine.c:436 (sofia/internal/3429 at 10.1.3.50) State RESET going to sleep
2012-10-31 09:31:37.595338 [NOTICE] switch_core_session.c:1449 Close Channel sofia/internal/sip:ukytvsci at 10.1.19.195:1292 [CS_DESTROY]
2012-10-31 09:31:37.595338 [DEBUG] sofia.c:6045 Channel sofia/internal/3429 at 10.1.3.50 entering state [calling][0]
2012-10-31 09:31:37.595338 [DEBUG] switch_core_state_machine.c:514 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Callstate Change HANGUP -> DOWN
2012-10-31 09:31:37.595338 [DEBUG] switch_core_state_machine.c:517 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) Running State Change CS_DESTROY
2012-10-31 09:31:37.595338 [DEBUG] switch_core_state_machine.c:527 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State DESTROY
2012-10-31 09:31:37.595338 [DEBUG] mod_sofia.c:374 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 SOFIA DESTROY
2012-10-31 09:31:37.595338 [DEBUG] switch_core_state_machine.c:86 sofia/internal/sip:ukytvsci at 10.1.19.195:1292 Standard DESTROY
2012-10-31 09:31:37.595338 [DEBUG] switch_core_state_machine.c:527 (sofia/internal/sip:ukytvsci at 10.1.19.195:1292) State DESTROY going to sleep
2012-10-31 09:31:37.595338 [DEBUG] sofia.c:6045 Channel sofia/internal/3429 at 10.1.3.50 entering state [terminated][500]
2012-10-31 09:31:37.595338 [DEBUG] switch_channel.c:2914 (sofia/internal/3429 at 10.1.3.50) Callstate Change ACTIVE -> HANGUP
2012-10-31 09:31:37.595338 [NOTICE] sofia.c:6837 Hangup sofia/internal/3429 at 10.1.3.50 [CS_RESET] [NORMAL_TEMPORARY_FAILURE]
2012-10-31 09:31:37.595338 [DEBUG] switch_channel.c:2937 Send signal sofia/internal/3429 at 10.1.3.50 [KILL]
2012-10-31 09:31:37.595338 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:31:37.595338 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/3429 at 10.1.3.50) Running State Change CS_HANGUP
2012-10-31 09:31:37.615316 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/3429 at 10.1.3.50) State HANGUP
2012-10-31 09:31:37.615316 [DEBUG] mod_sofia.c:463 sofia/internal/3429 at 10.1.3.50 Overriding SIP cause 503 with 500 from the other leg
2012-10-31 09:31:37.615316 [DEBUG] mod_sofia.c:469 Channel sofia/internal/3429 at 10.1.3.50 hanging up, cause: NORMAL_TEMPORARY_FAILURE
2012-10-31 09:31:37.615316 [DEBUG] switch_core_state_machine.c:47 sofia/internal/3429 at 10.1.3.50 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2012-10-31 09:31:37.615316 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/3429 at 10.1.3.50) State HANGUP going to sleep
2012-10-31 09:31:37.615316 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/3429 at 10.1.3.50) State Change CS_HANGUP -> CS_REPORTING
2012-10-31 09:31:37.615316 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:31:37.615316 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/3429 at 10.1.3.50) Running State Change CS_REPORTING
2012-10-31 09:31:37.615316 [DEBUG] switch_core_state_machine.c:685 (sofia/internal/3429 at 10.1.3.50) State REPORTING
2012-10-31 09:31:37.615316 [DEBUG] mod_cdr_sqlite.c:102 Writing SQL to DB: INSERT INTO cdr VALUES ("3429","3429","3606","MobEx_IP","2012-10-31 09:31:37","2012-10-31 09:31:51","2012-10-31 09:31:37",0,-14,"NORMAL_TEMPORARY_FAILURE","b6f8eb4d-19d0-46ee-983d-81175e7f222b","","3429")
2012-10-31 09:31:37.615316 [DEBUG] switch_core_state_machine.c:79 sofia/internal/3429 at 10.1.3.50 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
2012-10-31 09:31:37.615316 [DEBUG] switch_core_state_machine.c:685 (sofia/internal/3429 at 10.1.3.50) State REPORTING going to sleep
2012-10-31 09:31:37.615316 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/3429 at 10.1.3.50) State Change CS_REPORTING -> CS_DESTROY
2012-10-31 09:31:37.615316 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/3429 at 10.1.3.50 [BREAK]
2012-10-31 09:31:37.615316 [DEBUG] switch_core_session.c:1429 Session 1 (sofia/internal/3429 at 10.1.3.50) Locked, Waiting on external entities
2012-10-31 09:31:37.615316 [NOTICE] switch_core_session.c:1447 Session 1 (sofia/internal/3429 at 10.1.3.50) Ended
2012-10-31 09:31:37.615316 [NOTICE] switch_core_session.c:1449 Close Channel sofia/internal/3429 at 10.1.3.50 [CS_DESTROY]
2012-10-31 09:31:37.615316 [DEBUG] switch_core_state_machine.c:514 (sofia/internal/3429 at 10.1.3.50) Callstate Change HANGUP -> DOWN
2012-10-31 09:31:37.615316 [DEBUG] switch_core_state_machine.c:517 (sofia/internal/3429 at 10.1.3.50) Running State Change CS_DESTROY
2012-10-31 09:31:37.615316 [DEBUG] switch_core_state_machine.c:527 (sofia/internal/3429 at 10.1.3.50) State DESTROY
2012-10-31 09:31:37.615316 [DEBUG] mod_sofia.c:374 sofia/internal/3429 at 10.1.3.50 SOFIA DESTROY
2012-10-31 09:31:37.615316 [DEBUG] switch_core_state_machine.c:86 sofia/internal/3429 at 10.1.3.50 Standard DESTROY
2012-10-31 09:31:37.615316 [DEBUG] switch_core_state_machine.c:527 (sofia/internal/3429 at 10.1.3.50) State DESTROY going to sleep