2012-06-27 20:55:14.929462 [NOTICE] sofia.c:5930 Ring-Ready sofia/internal/sip:1001@10.10.57.82:50203!
2012-06-27 20:55:14.929462 [INFO] switch_ivr_originate.c:1156 Sending early media
2012-06-27 20:55:14.929462 [INFO] switch_nat.c:590 NAT port mapping disabled
2012-06-27 20:55:14.929462 [INFO] switch_nat.c:590 NAT port mapping disabled
2012-06-27 20:55:14.929462 [DEBUG] sofia.c:5838 Channel sofia/internal/sip:1001@10.10.57.82:50203 entering state [proceeding][180]
2012-06-27 20:55:14.929462 [DEBUG] sofia_glue.c:3269 AUDIO RTP [sofia/internal/1002@sukmad.dyndns-home.com:58180] 79.150.184.57 port 11154 -> 192.168.0.15 port 10000 codec: 98 ms: 30
2012-06-27 20:55:14.929462 [DEBUG] switch_rtp.c:1861 Starting timer [soft] 240 bytes per 30ms
2012-06-27 20:55:14.929462 [DEBUG] switch_rtp.c:2207 RTCP send rate is: 5000 and packet rate is: 30000 Remote Port: 10001
2012-06-27 20:55:14.929462 [DEBUG] switch_rtp.c:1230 Setting RTCP remote addr to 192.168.0.15:10001
2012-06-27 20:55:14.929462 [DEBUG] sofia_glue.c:3491 Setting Jitterbuffer to 90ms (3 frames)
2012-06-27 20:55:14.929462 [DEBUG] sofia_glue.c:3533 Set 2833 dtmf send payload to 101
2012-06-27 20:55:14.929462 [DEBUG] sofia_glue.c:3539 Set 2833 dtmf receive payload to 101
2012-06-27 20:55:14.929462 [DEBUG] sofia_glue.c:3566 sofia/internal/1002@sukmad.dyndns-home.com:58180 Set rtp dtmf delay to 40
2012-06-27 20:55:14.929462 [DEBUG] mod_sofia.c:2606 Ring SDP:
o=FreeSWITCH 1340812160 1340812161 IN IP4 79.150.184.57
m=audio 11154 RTP/AVP 98 101
a=rtpmap:101 telephone-event/8000
a=silenceSupp:off - - - -
2012-06-27 20:55:14.929462 [NOTICE] mod_sofia.c:2609 Pre-Answer sofia/internal/1002@sukmad.dyndns-home.com:58180!
2012-06-27 20:55:14.929462 [DEBUG] switch_channel.c:3042 (sofia/internal/1002@sukmad.dyndns-home.com:58180) Callstate Change RINGING -> EARLY
2012-06-27 20:55:14.929462 [DEBUG] switch_core_session.c:778 Send signal sofia/internal/1002@sukmad.dyndns-home.com:58180 [BREAK]
2012-06-27 20:55:14.929462 [DEBUG] switch_ivr_originate.c:1205 Raw Codec Activation Success L16@8000hz 1 channel 30ms
2012-06-27 20:55:14.929462 [DEBUG] switch_core_codec.c:219 sofia/internal/1002@sukmad.dyndns-home.com:58180 Push codec L16:70
2012-06-27 20:55:14.929462 [DEBUG] switch_ivr_originate.c:1268 Play Ringback Tone [%(2000,4000,440,480)]
2012-06-27 20:55:14.929462 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/1002@sukmad.dyndns-home.com:58180 [BREAK]
2012-06-27 20:55:14.929462 [DEBUG] sofia.c:5831 Channel sofia/internal/1002@sukmad.dyndns-home.com:58180 skipping state [early][183]
2012-06-27 20:55:14.939460 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:1001@31.4.238.246:22268 [BREAK]
2012-06-27 20:55:14.939460 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:1001@31.4.238.246:22268 [BREAK]
2012-06-27 20:55:14.939460 [DEBUG] sofia.c:5838 Channel sofia/internal/sip:1001@31.4.238.246:22268 entering state [proceeding][180]
2012-06-27 20:55:14.939460 [NOTICE] sofia.c:5930 Ring-Ready sofia/internal/sip:1001@31.4.238.246:22268!
2012-06-27 20:55:15.029459 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:1001@31.4.238.246:22268 [BREAK]
2012-06-27 20:55:15.029459 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:1001@31.4.238.246:22268 [BREAK]
2012-06-27 20:55:15.029459 [DEBUG] sofia.c:5838 Channel sofia/internal/sip:1001@31.4.238.246:22268 entering state [proceeding][180]
2012-06-27 20:55:15.069457 [DEBUG] switch_rtp.c:3527 Correct ip/port confirmed.
2012-06-27 20:55:26.079458 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:1001@10.10.57.82:50203 [BREAK]
2012-06-27 20:55:26.079458 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:1001@10.10.57.82:50203 [BREAK]
2012-06-27 20:55:26.079458 [DEBUG] sofia.c:5838 Channel sofia/internal/sip:1001@10.10.57.82:50203 entering state [completing][200]
2012-06-27 20:55:26.079458 [DEBUG] sofia.c:5849 Remote SDP:
o=- 3549812097 3549812099 IN IP4 10.10.57.82
m=audio 22010 RTP/AVP 99 101
a=rtpmap:101 telephone-event/8000
2012-06-27 20:55:26.079458 [DEBUG] sofia_glue.c:3941 Looking for zrtp-hash
2012-06-27 20:55:26.079458 [DEBUG] sofia_glue.c:3919 Deciding whether to pass zrtp-hash between legs
2012-06-27 20:55:26.079458 [DEBUG] sofia_glue.c:3921 CF_ZRTP_PASSTHRU_REQ not set, so not propagating zrtp-hash
2012-06-27 20:55:26.079458 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:1001@10.10.57.82:50203 [BREAK]
2012-06-27 20:55:26.079458 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/sip:1001@10.10.57.82:50203 [BREAK]
2012-06-27 20:55:26.079458 [DEBUG] sofia.c:5838 Channel sofia/internal/sip:1001@10.10.57.82:50203 entering state [ready][200]
2012-06-27 20:55:26.079458 [DEBUG] sofia_glue.c:3941 Looking for zrtp-hash
2012-06-27 20:55:26.079458 [DEBUG] sofia_glue.c:3919 Deciding whether to pass zrtp-hash between legs
2012-06-27 20:55:26.079458 [DEBUG] sofia_glue.c:3921 CF_ZRTP_PASSTHRU_REQ not set, so not propagating zrtp-hash
2012-06-27 20:55:26.079458 [DEBUG] sofia_glue.c:5034 Audio Codec Compare [iLBC:99:8000:30:0]/[SILK:119:16000:20:30000]
2012-06-27 20:55:26.079458 [DEBUG] sofia_glue.c:5034 Audio Codec Compare [telephone-event:101:8000:20:0]/[SILK:119:16000:20:30000]
2012-06-27 20:55:26.079458 [DEBUG] sofia_glue.c:5148 Set 2833 dtmf send payload to 101
2012-06-27 20:55:26.079458 [DEBUG] sofia_glue.c:5034 Audio Codec Compare [iLBC:99:8000:30:0]/[iLBC:97:8000:30:13330]
2012-06-27 20:55:26.079458 [DEBUG] sofia_glue.c:3020 Set Codec sofia/internal/sip:1001@10.10.57.82:50203 iLBC/8000 30 ms 240 samples 13330 bits
2012-06-27 20:55:26.079458 [DEBUG] switch_core_codec.c:111 sofia/internal/sip:1001@10.10.57.82:50203 Original read codec set to iLBC:97
2012-06-27 20:55:26.079458 [DEBUG] sofia_glue.c:5148 Set 2833 dtmf send payload to 101
2012-06-27 20:55:26.079458 [DEBUG] sofia_glue.c:3269 AUDIO RTP [sofia/internal/sip:1001@10.10.57.82:50203] 79.150.184.57 port 10388 -> 10.10.57.82 port 22010 codec: 99 ms: 30
2012-06-27 20:55:26.079458 [DEBUG] switch_rtp.c:1861 Starting timer [soft] 240 bytes per 30ms
2012-06-27 20:55:26.089461 [DEBUG] switch_rtp.c:2207 RTCP send rate is: 5000 and packet rate is: 30000 Remote Port: 22011
2012-06-27 20:55:26.089461 [DEBUG] switch_rtp.c:1230 Setting RTCP remote addr to 10.10.57.82:22011
2012-06-27 20:55:26.089461 [DEBUG] sofia_glue.c:3491 Setting Jitterbuffer to 90ms (3 frames)
2012-06-27 20:55:26.089461 [DEBUG] sofia_glue.c:3533 Set 2833 dtmf send payload to 101
2012-06-27 20:55:26.089461 [DEBUG] sofia_glue.c:3539 Set 2833 dtmf receive payload to 101
2012-06-27 20:55:26.089461 [DEBUG] sofia_glue.c:3566 sofia/internal/sip:1001@10.10.57.82:50203 Set rtp dtmf delay to 40
2012-06-27 20:55:26.089461 [DEBUG] switch_channel.c:3301 (sofia/internal/sip:1001@10.10.57.82:50203) Callstate Change RINGING -> ACTIVE
2012-06-27 20:55:26.089461 [DEBUG] switch_channel.c:3313 Send signal sofia/internal/1002@sukmad.dyndns-home.com:58180 [BREAK]
2012-06-27 20:55:26.089461 [NOTICE] sofia.c:6573 Channel [sofia/internal/sip:1001@10.10.57.82:50203] has been answered
2012-06-27 20:55:26.109459 [DEBUG] switch_core_codec.c:244 sofia/internal/1002@sukmad.dyndns-home.com:58180 Restore previous codec iLBC:97.
2012-06-27 20:55:26.109459 [DEBUG] switch_channel.c:2899 (sofia/internal/sip:1001@192.168.0.11:50199) Callstate Change RINGING -> HANGUP
2012-06-27 20:55:26.109459 [NOTICE] switch_ivr_originate.c:3257 Hangup sofia/internal/sip:1001@192.168.0.11:50199 [CS_CONSUME_MEDIA] [LOSE_RACE]
2012-06-27 20:55:26.109459 [DEBUG] switch_channel.c:2922 Send signal sofia/internal/sip:1001@192.168.0.11:50199 [KILL]
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:1001@192.168.0.11:50199 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:1001@192.168.0.11:50199) Running State Change CS_HANGUP
2012-06-27 20:55:26.109459 [DEBUG] switch_channel.c:2899 (sofia/internal/sip:1001@31.4.238.246:22268) Callstate Change RINGING -> HANGUP
2012-06-27 20:55:26.109459 [NOTICE] switch_ivr_originate.c:3257 Hangup sofia/internal/sip:1001@31.4.238.246:22268 [CS_CONSUME_MEDIA] [LOSE_RACE]
2012-06-27 20:55:26.109459 [DEBUG] switch_channel.c:2922 Send signal sofia/internal/sip:1001@31.4.238.246:22268 [KILL]
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/sip:1001@192.168.0.11:50199) State HANGUP
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:1001@31.4.238.246:22268 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] mod_sofia.c:469 Channel sofia/internal/sip:1001@192.168.0.11:50199 hanging up, cause: LOSE_RACE
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:1001@31.4.238.246:22268) Running State Change CS_HANGUP
2012-06-27 20:55:26.109459 [DEBUG] mod_sofia.c:527 Sending CANCEL to sofia/internal/sip:1001@192.168.0.11:50199
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:47 sofia/internal/sip:1001@192.168.0.11:50199 Standard HANGUP, cause: LOSE_RACE
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/sip:1001@192.168.0.11:50199) State HANGUP going to sleep
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/sip:1001@192.168.0.11:50199) State Change CS_HANGUP -> CS_REPORTING
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:1001@192.168.0.11:50199 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:1001@192.168.0.11:50199) Running State Change CS_REPORTING
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:685 (sofia/internal/sip:1001@192.168.0.11:50199) State REPORTING
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:79 sofia/internal/sip:1001@192.168.0.11:50199 Standard REPORTING, cause: LOSE_RACE
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:685 (sofia/internal/sip:1001@192.168.0.11:50199) State REPORTING going to sleep
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/sip:1001@31.4.238.246:22268) State HANGUP
2012-06-27 20:55:26.109459 [DEBUG] mod_sofia.c:469 Channel sofia/internal/sip:1001@31.4.238.246:22268 hanging up, cause: LOSE_RACE
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:1001@192.168.0.11:50199) State Change CS_REPORTING -> CS_DESTROY
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:1001@192.168.0.11:50199 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:1429 Session 15 (sofia/internal/sip:1001@192.168.0.11:50199) Locked, Waiting on external entities
2012-06-27 20:55:26.109459 [INFO] switch_nat.c:590 NAT port mapping disabled
2012-06-27 20:55:26.109459 [DEBUG] mod_sofia.c:527 Sending CANCEL to sofia/internal/sip:1001@31.4.238.246:22268
2012-06-27 20:55:26.109459 [DEBUG] mod_sofia.c:754 Local SDP sofia/internal/1002@sukmad.dyndns-home.com:58180:
o=FreeSWITCH 1340812160 1340812162 IN IP4 79.150.184.57
m=audio 11154 RTP/AVP 98 101
a=rtpmap:101 telephone-event/8000
a=silenceSupp:off - - - -
m=video 10766 RTP/AVP 34 103
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:47 sofia/internal/sip:1001@31.4.238.246:22268 Standard HANGUP, cause: LOSE_RACE
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/sip:1001@31.4.238.246:22268) State HANGUP going to sleep
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:416 (sofia/internal/sip:1001@31.4.238.246:22268) State Change CS_HANGUP -> CS_REPORTING
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:1001@31.4.238.246:22268 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:1001@31.4.238.246:22268) Running State Change CS_REPORTING
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:778 Send signal sofia/internal/1002@sukmad.dyndns-home.com:58180 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] switch_channel.c:3301 (sofia/internal/1002@sukmad.dyndns-home.com:58180) Callstate Change EARLY -> ACTIVE
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:685 (sofia/internal/sip:1001@31.4.238.246:22268) State REPORTING
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:79 sofia/internal/sip:1001@31.4.238.246:22268 Standard REPORTING, cause: LOSE_RACE
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:685 (sofia/internal/sip:1001@31.4.238.246:22268) State REPORTING going to sleep
2012-06-27 20:55:26.109459 [NOTICE] switch_ivr_originate.c:3284 Channel [sofia/internal/1002@sukmad.dyndns-home.com:58180] has been answered
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:1001@31.4.238.246:22268) State Change CS_REPORTING -> CS_DESTROY
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:1001@31.4.238.246:22268 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:1429 Session 17 (sofia/internal/sip:1001@31.4.238.246:22268) Locked, Waiting on external entities
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/1002@sukmad.dyndns-home.com:58180 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] sofia.c:5838 Channel sofia/internal/1002@sukmad.dyndns-home.com:58180 entering state [completed][200]
2012-06-27 20:55:26.109459 [DEBUG] switch_ivr_originate.c:3341 Originate Resulted in Success: [sofia/internal/sip:1001@10.10.57.82:50203]
2012-06-27 20:55:26.109459 [NOTICE] switch_core_session.c:1447 Session 15 (sofia/internal/sip:1001@192.168.0.11:50199) Ended
2012-06-27 20:55:26.109459 [NOTICE] switch_core_session.c:1447 Session 17 (sofia/internal/sip:1001@31.4.238.246:22268) Ended
2012-06-27 20:55:26.109459 [NOTICE] switch_core_session.c:1449 Close Channel sofia/internal/sip:1001@192.168.0.11:50199 [CS_DESTROY]
2012-06-27 20:55:26.109459 [NOTICE] switch_core_session.c:1449 Close Channel sofia/internal/sip:1001@31.4.238.246:22268 [CS_DESTROY]
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:514 (sofia/internal/sip:1001@31.4.238.246:22268) Callstate Change HANGUP -> DOWN
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:514 (sofia/internal/sip:1001@192.168.0.11:50199) Callstate Change HANGUP -> DOWN
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:517 (sofia/internal/sip:1001@31.4.238.246:22268) Running State Change CS_DESTROY
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:527 (sofia/internal/sip:1001@31.4.238.246:22268) State DESTROY
2012-06-27 20:55:26.109459 [DEBUG] mod_sofia.c:374 sofia/internal/sip:1001@31.4.238.246:22268 SOFIA DESTROY
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:86 sofia/internal/sip:1001@31.4.238.246:22268 Standard DESTROY
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:517 (sofia/internal/sip:1001@192.168.0.11:50199) Running State Change CS_DESTROY
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:527 (sofia/internal/sip:1001@31.4.238.246:22268) State DESTROY going to sleep
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:527 (sofia/internal/sip:1001@192.168.0.11:50199) State DESTROY
2012-06-27 20:55:26.109459 [DEBUG] mod_sofia.c:374 sofia/internal/sip:1001@192.168.0.11:50199 SOFIA DESTROY
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:86 sofia/internal/sip:1001@192.168.0.11:50199 Standard DESTROY
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:527 (sofia/internal/sip:1001@192.168.0.11:50199) State DESTROY going to sleep
2012-06-27 20:55:26.109459 [DEBUG] switch_ivr_originate.c:3341 Originate Resulted in Success: [sofia/internal/sip:1001@10.10.57.82:50203]
2012-06-27 20:55:26.109459 [DEBUG] mod_sofia.c:1603 sofia/internal/sip:1001@10.10.57.82:50203 PAUSE Jitterbuffer
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:778 Send signal sofia/internal/sip:1001@10.10.57.82:50203 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:778 Send signal sofia/internal/1002@sukmad.dyndns-home.com:58180 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] switch_ivr_bridge.c:1359 (sofia/internal/sip:1001@10.10.57.82:50203) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:1229 Send signal sofia/internal/sip:1001@10.10.57.82:50203 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:1001@10.10.57.82:50203) Running State Change CS_EXCHANGE_MEDIA
2012-06-27 20:55:26.109459 [DEBUG] switch_core_state_machine.c:443 (sofia/internal/sip:1001@10.10.57.82:50203) State EXCHANGE_MEDIA
2012-06-27 20:55:26.109459 [DEBUG] mod_sofia.c:582 SOFIA EXCHANGE_MEDIA
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/1002@sukmad.dyndns-home.com:58180 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/1002@sukmad.dyndns-home.com:58180 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:924 Send signal sofia/internal/1002@sukmad.dyndns-home.com:58180 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] sofia.c:5838 Channel sofia/internal/1002@sukmad.dyndns-home.com:58180 entering state [ready][200]
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:840 Send signal sofia/internal/sip:1001@10.10.57.82:50203 [BREAK]
2012-06-27 20:55:26.109459 [DEBUG] switch_core_session.c:840 Send signal sofia/internal/1002@sukmad.dyndns-home.com:58180 [BREAK]
2012-06-27 20:55:26.469460 [INFO] switch_rtp.c:3510 Auto Changing port from 10.10.57.82:22010 to 31.4.238.246:22267
2012-06-27 20:55:26.469460 [DEBUG] switch_rtp.c:1230 Setting RTCP remote addr to 31.4.238.246:22268
2012-06-27 20:55:38.009460 [DEBUG] sofia_reg.c:371 Registered sip.netelip.com