bad caller id and incoming calls not working

[horiz0n]

hi,
there are lot of problems with my configuration of bluebox:
i have couple of sip accounts to my sip provider like:
login1:pass...@sip.server.com/123456789
etc.
now, i created two trunks with external numbers: 587412757 and
587412762 and simple route for outgoing calls with regex: ^(\d{9})$
then created two external destinations:
587412757 with internal number to call 2001, and 587412762 with
internal number to call 2003.
Then in number manager i created two external (587412757 and
587412762) numbers with:
Type: External
Route: Device 2001 for 587412757 and 2003 for 587412762
contexts: Publicly Accessible
Number pools: Device and External Xfer
my configuration for number manager:
http://i41.tinypic.com/28i83g2.jpg

my configuration for device manager:
http://i40.tinypic.com/33vl0f6.jpg

now when i try to call outside, then both devices have the same
callerid number (587412762)
when somebody tries to call from outside, then connection is dropped.

outgoing log for 2001/587412757:

freeswitch@internal> 2012-04-11 07:41:52.881981 [DEBUG] sofia.c:6237
IP 192.168.1.111 Approved by acl "net_list_5[]". Access Granted.
2012-04-11 07:41:52.881981 [NOTICE] switch_channel.c:784 New Channel
sofia/sipinterface_1/accoun...@83.238.41.104 [9e4189b0-
ddc2-4438-934e-66e87c6689b1]
2012-04-11 07:41:52.883405 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/accoun...@83.238.41.104) Running State
Change CS_NEW
2012-04-11 07:41:52.883405 [DEBUG] switch_core_state_machine.c:324
(sofia/sipinterface_1/accoun...@83.238.41.104) State NEW
2012-04-11 07:41:53.096973 [DEBUG] sofia.c:7111 Setting NAT mode based
on rfc1918.auto
2012-04-11 07:41:53.096973 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/accoun...@83.238.41.104 entering state [received]
[100]
2012-04-11 07:41:53.096973 [DEBUG] sofia.c:4570 Remote SDP:
v=0
o=account_admin 8000 8000 IN IP4 192.168.1.111
s=SIP Call
c=IN IP4 192.168.1.111
t=0 0
m=audio 5004 RTP/AVP 9 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2012-04-11 07:41:53.096973 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [G722:9:8000:20:64000]/[G7221:115:32000:20:48000]
2012-04-11 07:41:53.096973 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [G722:9:8000:20:64000]/[G7221:107:16000:20:32000]
2012-04-11 07:41:53.096973 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [G722:9:8000:20:64000]/[G722:9:8000:20:64000]
2012-04-11 07:41:53.096973 [DEBUG] sofia_glue.c:2721 Set Codec sofia/
sipinterface_1/accoun...@83.238.41.104 G722/8000 20 ms 160 samples
64000 bits
2012-04-11 07:41:53.096973 [DEBUG] sofia_glue.c:4457 Set 2833 dtmf
send/recv payload to 101
2012-04-11 07:41:53.096973 [DEBUG] sofia.c:4732 (sofia/sipinterface_1/
accoun...@83.238.41.104) State Change CS_NEW -> CS_INIT
2012-04-11 07:41:53.096973 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/accoun...@83.238.41.104 [BREAK]
2012-04-11 07:41:53.097976 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/accoun...@83.238.41.104) Running State
Change CS_INIT
2012-04-11 07:41:53.097976 [DEBUG] switch_core_state_machine.c:342
(sofia/sipinterface_1/accoun...@83.238.41.104) State INIT
2012-04-11 07:41:53.097976 [DEBUG] mod_sofia.c:83 sofia/sipinterface_1/
accoun...@83.238.41.104 SOFIA INIT
2012-04-11 07:41:53.097976 [DEBUG] mod_sofia.c:123 (sofia/
sipinterface_1/accoun...@83.238.41.104) State Change CS_INIT ->
CS_ROUTING
2012-04-11 07:41:53.097976 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/accoun...@83.238.41.104 [BREAK]
2012-04-11 07:41:53.097976 [DEBUG] switch_core_state_machine.c:342
(sofia/sipinterface_1/accoun...@83.238.41.104) State INIT going to
sleep
2012-04-11 07:41:53.097976 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/accoun...@83.238.41.104) Running State
Change CS_ROUTING
2012-04-11 07:41:53.097976 [DEBUG] switch_channel.c:1615 (sofia/
sipinterface_1/accoun...@83.238.41.104) Callstate Change DOWN ->
RINGING
2012-04-11 07:41:53.097976 [DEBUG] switch_core_state_machine.c:345
(sofia/sipinterface_1/accoun...@83.238.41.104) State ROUTING
2012-04-11 07:41:53.097976 [DEBUG] mod_sofia.c:146 sofia/
sipinterface_1/accoun...@83.238.41.104 SOFIA ROUTING
2012-04-11 07:41:53.097976 [DEBUG] switch_core_state_machine.c:77
sofia/sipinterface_1/accoun...@83.238.41.104 Standard ROUTING
2012-04-11 07:41:53.097976 [INFO] mod_dialplan_xml.c:331 Processing
account_admin <account_admin>->224444444 in context context_2
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 parsing
[context_2->conditioning_callrecord] continue=true
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Absolute
Condition [conditioning_callrecord]
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
set(RECORD_TITLE=Recording ${destination_number} ${caller_id_number} $
{strftime(%Y-%m-%d %H:%M)})
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
set(RECORD_COPYRIGHT=(c) 2010 VoIP, Inc.)
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
set(RECORD_SOFTWARE=blue.box)
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
set(RECORD_ARTIST=2600hz)
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
set(RECORD_COMMENT=Automatically recorded via FreeSWITCH with
blue.box)
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
set(RECORD_DATE=${strftime(%Y-%m-%d %H:%M)})
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
set(RECORD_STEREO=true)
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 parsing
[context_2->conditioning_callerid] continue=true
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Regex
(FAIL) [conditioning_callerid] ${internal_caller_id_number}() =~ /^.+
$/ break=on-false
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 parsing
[context_2->postroute_global] continue=true
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Absolute
Condition [postroute_global]
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
hash(insert/${domain_name}-last_dial/${caller_id_number}/$
{destination_number})
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 parsing
[context_2->preanswer_callrecord_outbound] continue=true
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Regex
(FAIL) [preanswer_callrecord_outbound] ${callrecord_outbound}() =~ /^.+
$/ break=on-false
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 parsing
[context_2->main_trunk_4_pattern_5] continue=true
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Regex
(PASS) [main_trunk_4_pattern_5] destination_number(224444444) =~ /
^(\d{9})$/ break=on-false
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
set(prepend=)
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
set(effective_caller_id_name=587412762)
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
set(effective_caller_id_number=587412762)
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Regex
(FAIL) [main_trunk_4_pattern_5] ${outbound_caller_id_number}() =~ /^.+
$/ break=never
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Regex
(PASS) [main_trunk_4_pattern_5] destination_number(224444444) =~ /
^(\d{9})$/ break=on-false
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
bridge(sofia/gateway/trunk_4/${prepend}224444444)
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 parsing
[context_2->main_number_14] continue=true
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Regex
(FAIL) [main_number_14] destination_number(224444444) =~ /^587412762$/
break=on-false
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 parsing
[context_2->main_trunk_1_pattern_5] continue=true
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Regex
(PASS) [main_trunk_1_pattern_5] destination_number(224444444) =~ /
^(\d{9})$/ break=on-false
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
set(prepend=)
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
set(effective_caller_id_name=587412757)
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
set(effective_caller_id_number=587412757)
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Regex
(FAIL) [main_trunk_1_pattern_5] ${outbound_caller_id_number}() =~ /^.+
$/ break=never
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Regex
(PASS) [main_trunk_1_pattern_5] destination_number(224444444) =~ /
^(\d{9})$/ break=on-false
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Action
bridge(sofia/gateway/trunk_1/${prepend}224444444)
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 parsing
[context_2->main_number_11] continue=true
Dialplan: sofia/sipinterface_1/accoun...@83.238.41.104 Regex
(FAIL) [main_number_11] destination_number(224444444) =~ /^587412757$/
break=on-false
2012-04-11 07:41:53.097976 [DEBUG] switch_core_state_machine.c:119
(sofia/sipinterface_1/accoun...@83.238.41.104) State Change
CS_ROUTING -> CS_EXECUTE
2012-04-11 07:41:53.097976 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/accoun...@83.238.41.104 [BREAK]
2012-04-11 07:41:53.097976 [DEBUG] switch_core_state_machine.c:345
(sofia/sipinterface_1/accoun...@83.238.41.104) State ROUTING going
to sleep
2012-04-11 07:41:53.097976 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/accoun...@83.238.41.104) Running State
Change CS_EXECUTE
2012-04-11 07:41:53.097976 [DEBUG] switch_core_state_machine.c:352
(sofia/sipinterface_1/accoun...@83.238.41.104) State EXECUTE
2012-04-11 07:41:53.097976 [DEBUG] mod_sofia.c:239 sofia/
sipinterface_1/accoun...@83.238.41.104 SOFIA EXECUTE
2012-04-11 07:41:53.097976 [DEBUG] switch_core_state_machine.c:157
sofia/sipinterface_1/accoun...@83.238.41.104 Standard EXECUTE
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104
set(RECORD_TITLE=Recording 224444444 account_admin 2012-04-11 07:41)
2012-04-11 07:41:53.097976 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/accoun...@83.238.41.104 SET
[RECORD_TITLE]=[Recording 224444444 account_admin 2012-04-11 07:41]
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104
set(RECORD_COPYRIGHT=(c) 2010 VoIP, Inc.)
2012-04-11 07:41:53.097976 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/accoun...@83.238.41.104 SET [RECORD_COPYRIGHT]=[(c)
2010 VoIP, Inc.]
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104
set(RECORD_SOFTWARE=blue.box)
2012-04-11 07:41:53.097976 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/accoun...@83.238.41.104 SET
[RECORD_SOFTWARE]=[blue.box]
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104
set(RECORD_ARTIST=2600hz)
2012-04-11 07:41:53.097976 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/accoun...@83.238.41.104 SET
[RECORD_ARTIST]=[2600hz]
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104
set(RECORD_COMMENT=Automatically recorded via FreeSWITCH with
blue.box)
2012-04-11 07:41:53.097976 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/accoun...@83.238.41.104 SET
[RECORD_COMMENT]=[Automatically recorded via FreeSWITCH with blue.box]
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104
set(RECORD_DATE=2012-04-11 07:41)
2012-04-11 07:41:53.097976 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/accoun...@83.238.41.104 SET
[RECORD_DATE]=[2012-04-11 07:41]
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104
set(RECORD_STEREO=true)
2012-04-11 07:41:53.097976 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/accoun...@83.238.41.104 SET [RECORD_STEREO]=[true]
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104 hash(insert/
127.0.0.1-spymap/account_admin/9e4189b0-ddc2-4438-934e-66e87c6689b1)
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104 hash(insert/
127.0.0.1-last_dial/account_admin/224444444)
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104 hash(insert/
127.0.0.1-last_dial/global/9e4189b0-ddc2-4438-934e-66e87c6689b1)
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104
set(RFC2822_DATE=Wed, 11 Apr 2012 07:41:53 -0700)
2012-04-11 07:41:53.097976 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/accoun...@83.238.41.104 SET [RFC2822_DATE]=[Wed, 11
Apr 2012 07:41:53 -0700]
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104 set(prepend=)
2012-04-11 07:41:53.097976 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/accoun...@83.238.41.104 SET [prepend]=[UNDEF]
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104
set(effective_caller_id_name=587412762)
2012-04-11 07:41:53.102948 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/accoun...@83.238.41.104 SET
[effective_caller_id_name]=[587412762]
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104
set(effective_caller_id_number=587412762)
2012-04-11 07:41:53.102948 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/accoun...@83.238.41.104 SET
[effective_caller_id_number]=[587412762]
EXECUTE sofia/sipinterface_1/accoun...@83.238.41.104 bridge(sofia/
gateway/trunk_4/224444444)
2012-04-11 07:41:53.102948 [NOTICE] switch_channel.c:784 New Channel
sofia/sipinterface_1/224444444 [b8dd86fb-7e3b-4260-bddb-efddc6dcc938]
2012-04-11 07:41:53.297943 [DEBUG] mod_sofia.c:3968 (sofia/
sipinterface_1/224444444) State Change CS_NEW -> CS_INIT
2012-04-11 07:41:53.297943 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:41:53.297943 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/224444444) Running State Change CS_INIT
2012-04-11 07:41:53.297943 [DEBUG] switch_core_state_machine.c:342
(sofia/sipinterface_1/224444444) State INIT
2012-04-11 07:41:53.297943 [DEBUG] mod_sofia.c:83 sofia/
sipinterface_1/224444444 SOFIA INIT
2012-04-11 07:41:53.299043 [DEBUG] mod_sofia.c:123 (sofia/
sipinterface_1/224444444) State Change CS_INIT -> CS_ROUTING
2012-04-11 07:41:53.299043 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:41:53.299043 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/224444444 entering state [calling][0]
2012-04-11 07:41:53.299043 [DEBUG] switch_core_state_machine.c:342
(sofia/sipinterface_1/224444444) State INIT going to sleep
2012-04-11 07:41:53.299043 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/224444444) Running State Change CS_ROUTING
2012-04-11 07:41:53.299043 [DEBUG] switch_channel.c:1615 (sofia/
sipinterface_1/224444444) Callstate Change DOWN -> RINGING
2012-04-11 07:41:53.299043 [DEBUG] switch_core_state_machine.c:345
(sofia/sipinterface_1/224444444) State ROUTING
2012-04-11 07:41:53.299043 [DEBUG] mod_sofia.c:146 sofia/
sipinterface_1/224444444 SOFIA ROUTING
2012-04-11 07:41:53.299043 [DEBUG] switch_ivr_originate.c:66 (sofia/
sipinterface_1/224444444) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2012-04-11 07:41:53.299043 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:41:53.299043 [DEBUG] switch_core_state_machine.c:345
(sofia/sipinterface_1/224444444) State ROUTING going to sleep
2012-04-11 07:41:53.299043 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/224444444) Running State Change CS_CONSUME_MEDIA
2012-04-11 07:41:53.299043 [DEBUG] switch_core_state_machine.c:364
(sofia/sipinterface_1/224444444) State CONSUME_MEDIA
2012-04-11 07:41:53.299043 [DEBUG] switch_core_state_machine.c:364
(sofia/sipinterface_1/224444444) State CONSUME_MEDIA going to sleep
2012-04-11 07:41:53.309944 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/224444444 entering state [calling][0]
2012-04-11 07:41:54.652889 [INFO] sofia.c:709 sofia/
sipinterface_1/224444444 Update Callee ID to "224444444" <224444444>
2012-04-11 07:41:54.888881 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/224444444 entering state [proceeding][183]
2012-04-11 07:41:54.888881 [DEBUG] sofia.c:4570 Remote SDP:
v=0
o=FreeSWITCH 8380000213841201760 239546126434116570 IN IP4
217.153.192.143
s=FreeSWITCH
c=IN IP4 217.153.192.143
t=0 0
m=audio 11416 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

2012-04-11 07:41:54.888881 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000]
2012-04-11 07:41:54.888881 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMU:0:8000:20:64000]/[G7221:115:32000:20:48000]
2012-04-11 07:41:54.888881 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMU:0:8000:20:64000]/[G7221:107:16000:20:32000]
2012-04-11 07:41:54.888881 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000]
2012-04-11 07:41:54.888881 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2012-04-11 07:41:54.888881 [DEBUG] sofia_glue.c:2721 Set Codec sofia/
sipinterface_1/224444444 PCMU/8000 20 ms 160 samples 64000 bits
2012-04-11 07:41:54.888881 [DEBUG] sofia_glue.c:4451 Set 2833 dtmf
send payload to 101
2012-04-11 07:41:54.888881 [DEBUG] sofia_glue.c:2961 AUDIO RTP [sofia/
sipinterface_1/224444444] 83.238.41.104 port 22976 -> 217.153.192.143
port 11416 codec: 0 ms: 20
2012-04-11 07:41:54.888881 [DEBUG] switch_rtp.c:1418 Starting timer
[soft] 160 bytes per 20ms
2012-04-11 07:41:54.890884 [DEBUG] sofia_glue.c:3179 Set 2833 dtmf
send payload to 101
2012-04-11 07:41:54.890884 [DEBUG] sofia_glue.c:3184 Set 2833 dtmf
receive payload to 101
2012-04-11 07:41:54.890884 [DEBUG] sofia_glue.c:3195 Set comfort noise
payload to 13
2012-04-11 07:41:54.890884 [NOTICE] sofia_glue.c:3591 Pre-Answer sofia/
sipinterface_1/224444444!
2012-04-11 07:41:54.890884 [DEBUG] switch_channel.c:2544 (sofia/
sipinterface_1/224444444) Callstate Change RINGING -> EARLY
2012-04-11 07:41:54.890884 [DEBUG] switch_channel.c:2588 Send signal
sofia/sipinterface_1/accoun...@83.238.41.104 [BREAK]
2012-04-11 07:41:54.990876 [INFO] switch_ivr_originate.c:3290 Sending
early media
2012-04-11 07:41:54.990876 [DEBUG] sofia_glue.c:2961 AUDIO RTP [sofia/
sipinterface_1/accoun...@83.238.41.104] 83.238.41.104 port 24166 -
> 192.168.1.111 port 5004 codec: 9 ms: 20
2012-04-11 07:41:54.991913 [DEBUG] switch_rtp.c:1418 Starting timer
[soft] 160 bytes per 20ms
2012-04-11 07:41:54.992928 [DEBUG] sofia_glue.c:3179 Set 2833 dtmf
send payload to 101
2012-04-11 07:41:54.992928 [DEBUG] sofia_glue.c:3184 Set 2833 dtmf
receive payload to 101
2012-04-11 07:41:54.992928 [DEBUG] mod_sofia.c:2169 Ring SDP:
v=0
o=FreeSWITCH 1334131148 1334131149 IN IP4 83.238.41.104
s=FreeSWITCH
c=IN IP4 83.238.41.104
t=0 0
m=audio 24166 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2012-04-11 07:41:54.992928 [NOTICE] mod_sofia.c:2172 Pre-Answer sofia/
sipinterface_1/accoun...@83.238.41.104!
2012-04-11 07:41:54.992928 [DEBUG] switch_channel.c:2544 (sofia/
sipinterface_1/accoun...@83.238.41.104) Callstate Change RINGING -
> EARLY
2012-04-11 07:41:54.992928 [DEBUG] switch_core_session.c:676 Send
signal sofia/sipinterface_1/accoun...@83.238.41.104 [BREAK]
2012-04-11 07:41:54.992928 [DEBUG] switch_ivr_originate.c:3333
Originate Resulted in Success: [sofia/sipinterface_1/224444444]
2012-04-11 07:41:54.992928 [DEBUG] switch_core_session.c:676 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:41:54.992928 [DEBUG] switch_core_session.c:676 Send
signal sofia/sipinterface_1/accoun...@83.238.41.104 [BREAK]
2012-04-11 07:41:54.992928 [DEBUG] switch_ivr_bridge.c:1226 (sofia/
sipinterface_1/224444444) State Change CS_CONSUME_MEDIA ->
CS_EXCHANGE_MEDIA
2012-04-11 07:41:54.992928 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:41:54.993949 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/224444444) Running State Change
CS_EXCHANGE_MEDIA
2012-04-11 07:41:54.993949 [DEBUG] switch_core_state_machine.c:355
(sofia/sipinterface_1/224444444) State EXCHANGE_MEDIA
2012-04-11 07:41:54.993949 [DEBUG] mod_sofia.c:551 SOFIA
EXCHANGE_MEDIA
2012-04-11 07:41:54.993949 [DEBUG] sofia.c:4554 Channel sofia/
sipinterface_1/accoun...@83.238.41.104 skipping state [early][183]
2012-04-11 07:41:55.028876 [DEBUG] switch_rtp.c:2544 Correct ip/port
confirmed.
2012-04-11 07:41:55.088872 [DEBUG] switch_rtp.c:2544 Correct ip/port
confirmed.
2012-04-11 07:41:55.688848 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/224444444 entering state [completing][200]
2012-04-11 07:41:55.688848 [DEBUG] sofia.c:4567 Duplicate SDP
v=0
o=FreeSWITCH 8380000213841201760 239546126434116570 IN IP4
217.153.192.143
s=FreeSWITCH
c=IN IP4 217.153.192.143
t=0 0
m=audio 11416 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

2012-04-11 07:41:55.688848 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/224444444 entering state [ready][200]
2012-04-11 07:41:55.688848 [DEBUG] switch_channel.c:2694 (sofia/
sipinterface_1/224444444) Callstate Change EARLY -> ACTIVE
2012-04-11 07:41:55.689941 [DEBUG] switch_channel.c:2706 Send signal
sofia/sipinterface_1/accoun...@83.238.41.104 [BREAK]
2012-04-11 07:41:55.689941 [NOTICE] sofia.c:5083 Channel [sofia/
sipinterface_1/224444444] has been answered
2012-04-11 07:41:55.873841 [DEBUG] mod_sofia.c:680 Local SDP sofia/
sipinterface_1/accoun...@83.238.41.104:
v=0
o=FreeSWITCH 1334131148 1334131150 IN IP4 83.238.41.104
s=FreeSWITCH
c=IN IP4 83.238.41.104
t=0 0
m=audio 24166 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2012-04-11 07:41:55.873841 [DEBUG] switch_core_session.c:676 Send
signal sofia/sipinterface_1/accoun...@83.238.41.104 [BREAK]
2012-04-11 07:41:55.873841 [DEBUG] switch_channel.c:2694 (sofia/
sipinterface_1/accoun...@83.238.41.104) Callstate Change EARLY ->
ACTIVE
2012-04-11 07:41:55.873841 [NOTICE] switch_ivr_bridge.c:398 Channel
[sofia/sipinterface_1/accoun...@83.238.41.104] has been answered
2012-04-11 07:41:55.874915 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/accoun...@83.238.41.104 entering state [completed]
[200]
2012-04-11 07:41:55.893842 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/accoun...@83.238.41.104 entering state [ready][200]
2012-04-11 07:41:55.908845 [DEBUG] switch_core_session.c:738 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:41:55.908845 [DEBUG] switch_core_session.c:738 Send
signal sofia/sipinterface_1/accoun...@83.238.41.104 [BREAK]

2012-04-11 07:42:16.182024 [DEBUG] switch_channel.c:2457 (sofia/
sipinterface_1/accoun...@83.238.41.104) Callstate Change ACTIVE ->
HANGUP
2012-04-11 07:42:16.182024 [NOTICE] sofia.c:528 Hangup sofia/
sipinterface_1/accoun...@83.238.41.104 [CS_EXECUTE]
[NORMAL_CLEARING]
2012-04-11 07:42:16.182024 [DEBUG] switch_channel.c:2473 Send signal
sofia/sipinterface_1/accoun...@83.238.41.104 [KILL]
2012-04-11 07:42:16.182024 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/accoun...@83.238.41.104 [BREAK]
2012-04-11 07:42:16.190032 [DEBUG] switch_ivr_bridge.c:483 sofia/
sipinterface_1/accoun...@83.238.41.104 ending bridge by request
from read function
2012-04-11 07:42:16.190032 [DEBUG] switch_ivr_bridge.c:564 BRIDGE
THREAD DONE [sofia/sipinterface_1/accoun...@83.238.41.104]
2012-04-11 07:42:16.190032 [DEBUG] switch_ivr_bridge.c:584 Send signal
sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:42:16.190032 [DEBUG] switch_ivr_bridge.c:564 BRIDGE
THREAD DONE [sofia/sipinterface_1/224444444]
2012-04-11 07:42:16.190032 [DEBUG] switch_ivr_bridge.c:584 Send signal
sofia/sipinterface_1/accoun...@83.238.41.104 [BREAK]
2012-04-11 07:42:16.190032 [DEBUG] switch_channel.c:2457 (sofia/
sipinterface_1/224444444) Callstate Change ACTIVE -> HANGUP
2012-04-11 07:42:16.190032 [NOTICE] switch_ivr_bridge.c:636 Hangup
sofia/sipinterface_1/224444444 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2012-04-11 07:42:16.190032 [DEBUG] switch_channel.c:2473 Send signal
sofia/sipinterface_1/224444444 [KILL]
2012-04-11 07:42:16.190032 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:42:16.190032 [DEBUG] switch_core_state_machine.c:355
(sofia/sipinterface_1/224444444) State EXCHANGE_MEDIA going to sleep
2012-04-11 07:42:16.190032 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/224444444) Running State Change CS_HANGUP
2012-04-11 07:42:16.190032 [DEBUG] switch_core_state_machine.c:539
(sofia/sipinterface_1/224444444) State HANGUP
2012-04-11 07:42:16.190032 [DEBUG] mod_sofia.c:450 sofia/
sipinterface_1/224444444 Overriding SIP cause 480 with 200 from the
other leg
2012-04-11 07:42:16.190032 [DEBUG] mod_sofia.c:456 Channel sofia/
sipinterface_1/224444444 hanging up, cause: NORMAL_CLEARING
2012-04-11 07:42:16.192027 [DEBUG] switch_ivr_bridge.c:1297 sofia/
sipinterface_1/224444444 skip receive message [UNBRIDGE] (channel is
hungup already)
2012-04-11 07:42:16.192027 [DEBUG] switch_ivr_bridge.c:1300 sofia/
sipinterface_1/accoun...@83.238.41.104 skip receive message
[UNBRIDGE] (channel is hungup already)
2012-04-11 07:42:16.192027 [DEBUG] switch_core_session.c:1933 sofia/
sipinterface_1/accoun...@83.238.41.104 skip receive message
[APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2012-04-11 07:42:16.192027 [DEBUG] switch_core_state_machine.c:352
(sofia/sipinterface_1/accoun...@83.238.41.104) State EXECUTE going
to sleep
2012-04-11 07:42:16.192027 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/accoun...@83.238.41.104) Running State
Change CS_HANGUP
2012-04-11 07:42:16.192027 [DEBUG] switch_core_state_machine.c:539
(sofia/sipinterface_1/accoun...@83.238.41.104) State HANGUP
2012-04-11 07:42:16.192027 [DEBUG] mod_sofia.c:450 sofia/
sipinterface_1/accoun...@83.238.41.104 Overriding SIP cause 480
with 200 from the other leg
2012-04-11 07:42:16.192027 [DEBUG] mod_sofia.c:456 Channel sofia/
sipinterface_1/accoun...@83.238.41.104 hanging up, cause:
NORMAL_CLEARING
2012-04-11 07:42:16.470017 [DEBUG] mod_sofia.c:499 Sending BYE to
sofia/sipinterface_1/224444444
2012-04-11 07:42:16.470017 [DEBUG] switch_core_state_machine.c:46
sofia/sipinterface_1/224444444 Standard HANGUP, cause: NORMAL_CLEARING
2012-04-11 07:42:16.470017 [DEBUG] switch_core_state_machine.c:539
(sofia/sipinterface_1/224444444) State HANGUP going to sleep
2012-04-11 07:42:16.470017 [DEBUG] switch_core_state_machine.c:337
(sofia/sipinterface_1/224444444) State Change CS_HANGUP ->
CS_REPORTING
2012-04-11 07:42:16.470017 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:42:16.470017 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/224444444) Running State Change CS_REPORTING
2012-04-11 07:42:16.470017 [DEBUG] switch_core_state_machine.c:599
(sofia/sipinterface_1/224444444) State REPORTING
2012-04-11 07:42:16.470017 [DEBUG] switch_core_state_machine.c:53
sofia/sipinterface_1/224444444 Standard REPORTING, cause:
NORMAL_CLEARING
2012-04-11 07:42:16.470017 [DEBUG] switch_core_state_machine.c:599
(sofia/sipinterface_1/224444444) State REPORTING going to sleep
2012-04-11 07:42:16.470017 [DEBUG] switch_core_state_machine.c:331
(sofia/sipinterface_1/224444444) State Change CS_REPORTING ->
CS_DESTROY
2012-04-11 07:42:16.470017 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:42:16.470017 [DEBUG] switch_core_session.c:1224 Session
170 (sofia/sipinterface_1/224444444) Locked, Waiting on external
entities
2012-04-11 07:42:16.470017 [NOTICE] switch_core_session.c:1242 Session
170 (sofia/sipinterface_1/224444444) Ended
2012-04-11 07:42:16.470017 [NOTICE] switch_core_session.c:1244 Close
Channel sofia/sipinterface_1/224444444 [CS_DESTROY]
2012-04-11 07:42:16.470017 [DEBUG] switch_core_state_machine.c:431
(sofia/sipinterface_1/224444444) Callstate Change HANGUP -> DOWN
2012-04-11 07:42:16.470017 [DEBUG] switch_core_state_machine.c:434
(sofia/sipinterface_1/224444444) Running State Change CS_DESTROY
2012-04-11 07:42:16.470017 [DEBUG] switch_core_state_machine.c:444
(sofia/sipinterface_1/224444444) State DESTROY
2012-04-11 07:42:16.470017 [DEBUG] mod_sofia.c:361 sofia/
sipinterface_1/224444444 SOFIA DESTROY
2012-04-11 07:42:16.470017 [DEBUG] switch_core_state_machine.c:60
sofia/sipinterface_1/224444444 Standard DESTROY
2012-04-11 07:42:16.470017 [DEBUG] switch_core_state_machine.c:444
(sofia/sipinterface_1/224444444) State DESTROY going to sleep
2012-04-11 07:42:16.594007 [DEBUG] switch_core_state_machine.c:46
sofia/sipinterface_1/accoun...@83.238.41.104 Standard HANGUP,
cause: NORMAL_CLEARING
2012-04-11 07:42:16.594007 [DEBUG] switch_core_state_machine.c:539
(sofia/sipinterface_1/accoun...@83.238.41.104) State HANGUP going
to sleep
2012-04-11 07:42:16.594007 [DEBUG] switch_core_state_machine.c:337
(sofia/sipinterface_1/accoun...@83.238.41.104) State Change
CS_HANGUP -> CS_REPORTING
2012-04-11 07:42:16.594007 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/accoun...@83.238.41.104 [BREAK]
2012-04-11 07:42:16.594007 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/accoun...@83.238.41.104) Running State
Change CS_REPORTING
2012-04-11 07:42:16.594007 [DEBUG] switch_core_state_machine.c:599
(sofia/sipinterface_1/accoun...@83.238.41.104) State REPORTING
2012-04-11 07:42:16.594007 [DEBUG] switch_core_state_machine.c:53
sofia/sipinterface_1/accoun...@83.238.41.104 Standard REPORTING,
cause: NORMAL_CLEARING
2012-04-11 07:42:16.594007 [DEBUG] switch_core_state_machine.c:599
(sofia/sipinterface_1/accoun...@83.238.41.104) State REPORTING
going to sleep
2012-04-11 07:42:16.594007 [DEBUG] switch_core_state_machine.c:331
(sofia/sipinterface_1/accoun...@83.238.41.104) State Change
CS_REPORTING -> CS_DESTROY
2012-04-11 07:42:16.594007 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/accoun...@83.238.41.104 [BREAK]
2012-04-11 07:42:16.594007 [DEBUG] switch_core_session.c:1224 Session
169 (sofia/sipinterface_1/accoun...@83.238.41.104) Locked, Waiting
on external entities
2012-04-11 07:42:16.594007 [NOTICE] switch_core_session.c:1242 Session
169 (sofia/sipinterface_1/accoun...@83.238.41.104) Ended
2012-04-11 07:42:16.594007 [NOTICE] switch_core_session.c:1244 Close
Channel sofia/sipinterface_1/accoun...@83.238.41.104 [CS_DESTROY]
2012-04-11 07:42:16.596231 [DEBUG] switch_core_state_machine.c:431
(sofia/sipinterface_1/accoun...@83.238.41.104) Callstate Change
HANGUP -> DOWN
2012-04-11 07:42:16.596231 [DEBUG] switch_core_state_machine.c:434
(sofia/sipinterface_1/accoun...@83.238.41.104) Running State
Change CS_DESTROY
2012-04-11 07:42:16.596231 [DEBUG] switch_core_state_machine.c:444
(sofia/sipinterface_1/accoun...@83.238.41.104) State DESTROY
2012-04-11 07:42:16.596231 [DEBUG] mod_sofia.c:361 sofia/
sipinterface_1/accoun...@83.238.41.104 SOFIA DESTROY
2012-04-11 07:42:16.596231 [DEBUG] switch_core_state_machine.c:60
sofia/sipinterface_1/accoun...@83.238.41.104 Standard DESTROY
2012-04-11 07:42:16.596231 [DEBUG] switch_core_state_machine.c:444
(sofia/sipinterface_1/accoun...@83.238.41.104) State DESTROY going
to sleep

incoming log for 587412757:

2012-04-11 07:38:27.889104 [DEBUG] sofia.c:6237 IP 217.153.192.153
Approved by acl "net_list_5[]". Access Granted.
2012-04-11 07:38:27.889104 [NOTICE] switch_channel.c:784 New Channel
sofia/sipinterface_1/7283...@217.153.192.143 [2b6eb3cd-
f098-44d6-9897-4cf6e6842c41]
2012-04-11 07:38:27.891536 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/7283...@217.153.192.143) Running State Change
CS_NEW
2012-04-11 07:38:27.891536 [DEBUG] switch_core_state_machine.c:324
(sofia/sipinterface_1/7283...@217.153.192.143) State NEW
2012-04-11 07:38:28.143094 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/7283...@217.153.192.143 entering state [received]
[100]
2012-04-11 07:38:28.143094 [DEBUG] sofia.c:4570 Remote SDP:
v=0
o=FreeSWITCH 8492788955963155627 5792137785957400971 IN IP4
217.153.192.143
s=FreeSWITCH
c=IN IP4 217.153.192.143
t=0 0
m=audio 15760 RTP/AVP 8 0 2 3 102 18 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:2 AAL2-G726-32/8000
a=rtpmap:3 GSM/8000
a=rtpmap:102 iLBC/8000
a=fmtp:102 mode=30
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20

2012-04-11 07:38:28.143094 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMA:8:8000:20:64000]/[G7221:115:32000:20:48000]
2012-04-11 07:38:28.143094 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMA:8:8000:20:64000]/[G7221:107:16000:20:32000]
2012-04-11 07:38:28.143094 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000]
2012-04-11 07:38:28.143094 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2012-04-11 07:38:28.143094 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2012-04-11 07:38:28.143094 [DEBUG] sofia_glue.c:2721 Set Codec sofia/
sipinterface_1/7283...@217.153.192.143 PCMA/8000 20 ms 160 samples
64000 bits
2012-04-11 07:38:28.143094 [DEBUG] sofia_glue.c:4457 Set 2833 dtmf
send/recv payload to 101
2012-04-11 07:38:28.143094 [DEBUG] sofia.c:4732 (sofia/
sipinterface_1/7283...@217.153.192.143) State Change CS_NEW ->
CS_INIT
2012-04-11 07:38:28.143094 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/7283...@217.153.192.143 [BREAK]
2012-04-11 07:38:28.145097 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/7283...@217.153.192.143) Running State Change
CS_INIT
2012-04-11 07:38:28.145097 [DEBUG] switch_core_state_machine.c:342
(sofia/sipinterface_1/7283...@217.153.192.143) State INIT
2012-04-11 07:38:28.145097 [DEBUG] mod_sofia.c:83 sofia/
sipinterface_1/7283...@217.153.192.143 SOFIA INIT
2012-04-11 07:38:28.145097 [DEBUG] mod_sofia.c:123 (sofia/
sipinterface_1/7283...@217.153.192.143) State Change CS_INIT ->
CS_ROUTING
2012-04-11 07:38:28.145097 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/7283...@217.153.192.143 [BREAK]
2012-04-11 07:38:28.145097 [DEBUG] switch_core_state_machine.c:342
(sofia/sipinterface_1/7283...@217.153.192.143) State INIT going to
sleep
2012-04-11 07:38:28.145097 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/7283...@217.153.192.143) Running State Change
CS_ROUTING
2012-04-11 07:38:28.145097 [DEBUG] switch_channel.c:1615 (sofia/
sipinterface_1/7283...@217.153.192.143) Callstate Change DOWN ->
RINGING
2012-04-11 07:38:28.145097 [DEBUG] switch_core_state_machine.c:345
(sofia/sipinterface_1/7283...@217.153.192.143) State ROUTING
2012-04-11 07:38:28.145097 [DEBUG] mod_sofia.c:146 sofia/
sipinterface_1/7283...@217.153.192.143 SOFIA ROUTING
2012-04-11 07:38:28.145097 [DEBUG] switch_core_state_machine.c:77
sofia/sipinterface_1/7283...@217.153.192.143 Standard ROUTING
2012-04-11 07:38:28.145097 [INFO] mod_dialplan_xml.c:331 Processing
728331224 <728331224>->iqservice009 in context context_2
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->conditioning_callrecord] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Absolute
Condition [conditioning_callrecord]
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RECORD_TITLE=Recording ${destination_number} ${caller_id_number} $
{strftime(%Y-%m-%d %H:%M)})
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RECORD_COPYRIGHT=(c) 2010 VoIP, Inc.)
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RECORD_SOFTWARE=blue.box)
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RECORD_ARTIST=2600hz)
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RECORD_COMMENT=Automatically recorded via FreeSWITCH with
blue.box)
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RECORD_DATE=${strftime(%Y-%m-%d %H:%M)})
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RECORD_STEREO=true)
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->conditioning_callerid] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Regex (FAIL)
[conditioning_callerid] ${internal_caller_id_number}() =~ /^.+$/
break=on-false
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->postroute_global] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Absolute
Condition [postroute_global]
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
hash(insert/${domain_name}-last_dial/${caller_id_number}/$
{destination_number})
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->preanswer_callrecord_outbound] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Regex (FAIL)
[preanswer_callrecord_outbound] ${callrecord_outbound}() =~ /^.+$/
break=on-false
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->main_trunk_4_pattern_5] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Regex (FAIL)
[main_trunk_4_pattern_5] destination_number(iqservice009) =~ /^(\d{9})
$/ break=on-false
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->main_number_14] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Regex (FAIL)
[main_number_14] destination_number(iqservice009) =~ /^587412762$/
break=on-false
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->main_trunk_1_pattern_5] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Regex (FAIL)
[main_trunk_1_pattern_5] destination_number(iqservice009) =~ /^(\d{9})
$/ break=on-false
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->main_number_11] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Regex (FAIL)
[main_number_11] destination_number(iqservice009) =~ /^587412757$/
break=on-false
2012-04-11 07:38:28.145097 [DEBUG] switch_core_state_machine.c:119
(sofia/sipinterface_1/7283...@217.153.192.143) State Change
CS_ROUTING -> CS_EXECUTE
2012-04-11 07:38:28.145097 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/7283...@217.153.192.143 [BREAK]
2012-04-11 07:38:28.145097 [DEBUG] switch_core_state_machine.c:345
(sofia/sipinterface_1/7283...@217.153.192.143) State ROUTING going
to sleep
2012-04-11 07:38:28.145097 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/7283...@217.153.192.143) Running State Change
CS_EXECUTE
2012-04-11 07:38:28.145097 [DEBUG] switch_core_state_machine.c:352
(sofia/sipinterface_1/7283...@217.153.192.143) State EXECUTE
2012-04-11 07:38:28.145097 [DEBUG] mod_sofia.c:239 sofia/
sipinterface_1/7283...@217.153.192.143 SOFIA EXECUTE
2012-04-11 07:38:28.145097 [DEBUG] switch_core_state_machine.c:157
sofia/sipinterface_1/7283...@217.153.192.143 Standard EXECUTE
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RECORD_TITLE=Recording iqservice009 728331224 2012-04-11 07:38)
2012-04-11 07:38:28.145097 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET [RECORD_TITLE]=[Recording
iqservice009 728331224 2012-04-11 07:38]
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RECORD_COPYRIGHT=(c) 2010 VoIP, Inc.)
2012-04-11 07:38:28.145097 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET [RECORD_COPYRIGHT]=[(c)
2010 VoIP, Inc.]
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RECORD_SOFTWARE=blue.box)
2012-04-11 07:38:28.145097 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET
[RECORD_SOFTWARE]=[blue.box]
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RECORD_ARTIST=2600hz)
2012-04-11 07:38:28.148428 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET [RECORD_ARTIST]=[2600hz]
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RECORD_COMMENT=Automatically recorded via FreeSWITCH with
blue.box)
2012-04-11 07:38:28.148428 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET
[RECORD_COMMENT]=[Automatically recorded via FreeSWITCH with blue.box]
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RECORD_DATE=2012-04-11 07:38)
2012-04-11 07:38:28.148428 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET [RECORD_DATE]=[2012-04-11
07:38]
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RECORD_STEREO=true)
2012-04-11 07:38:28.148428 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET [RECORD_STEREO]=[true]
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143 hash(insert/
127.0.0.1-spymap/728331224/2b6eb3cd-f098-44d6-9897-4cf6e6842c41)
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143 hash(insert/
127.0.0.1-last_dial/728331224/iqservice009)
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143 hash(insert/
127.0.0.1-last_dial/global/2b6eb3cd-f098-44d6-9897-4cf6e6842c41)
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RFC2822_DATE=Wed, 11 Apr 2012 07:38:28 -0700)
2012-04-11 07:38:28.148428 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET [RFC2822_DATE]=[Wed, 11
Apr 2012 07:38:28 -0700]
2012-04-11 07:38:28.148428 [NOTICE] switch_core_state_machine.c:189
sofia/sipinterface_1/7283...@217.153.192.143 has executed the last
dialplan instruction, hanging up.
2012-04-11 07:38:28.148428 [DEBUG] switch_channel.c:2457 (sofia/
sipinterface_1/7283...@217.153.192.143) Callstate Change RINGING ->
HANGUP
2012-04-11 07:38:28.148428 [NOTICE] switch_core_state_machine.c:191
Hangup sofia/sipinterface_1/7283...@217.153.192.143 [CS_EXECUTE]
[NORMAL_CLEARING]
2012-04-11 07:38:28.148428 [DEBUG] switch_channel.c:2473 Send signal
sofia/sipinterface_1/7283...@217.153.192.143 [KILL]
2012-04-11 07:38:28.148428 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/7283...@217.153.192.143 [BREAK]
2012-04-11 07:38:28.148428 [DEBUG] switch_core_state_machine.c:352
(sofia/sipinterface_1/7283...@217.153.192.143) State EXECUTE going
to sleep
2012-04-11 07:38:28.148428 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/7283...@217.153.192.143) Running State Change
CS_HANGUP
2012-04-11 07:38:28.148428 [DEBUG] switch_core_state_machine.c:539
(sofia/sipinterface_1/7283...@217.153.192.143) State HANGUP
2012-04-11 07:38:28.148428 [DEBUG] mod_sofia.c:456 Channel sofia/
sipinterface_1/7283...@217.153.192.143 hanging up, cause:
NORMAL_CLEARING
2012-04-11 07:38:28.302060 [DEBUG] mod_sofia.c:518 Responding to
INVITE with: 480
2012-04-11 07:38:28.302060 [DEBUG] switch_core_state_machine.c:46
sofia/sipinterface_1/7283...@217.153.192.143 Standard HANGUP, cause:
NORMAL_CLEARING
2012-04-11 07:38:28.302060 [DEBUG] switch_core_state_machine.c:539
(sofia/sipinterface_1/7283...@217.153.192.143) State HANGUP going to
sleep
2012-04-11 07:38:28.302060 [DEBUG] switch_core_state_machine.c:337
(sofia/sipinterface_1/7283...@217.153.192.143) State Change
CS_HANGUP -> CS_REPORTING
2012-04-11 07:38:28.302060 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/7283...@217.153.192.143 [BREAK]
2012-04-11 07:38:28.302060 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/7283...@217.153.192.143) Running State Change
CS_REPORTING
2012-04-11 07:38:28.302060 [DEBUG] switch_core_state_machine.c:599
(sofia/sipinterface_1/7283...@217.153.192.143) State REPORTING
2012-04-11 07:38:28.302060 [DEBUG] switch_core_state_machine.c:53
sofia/sipinterface_1/7283...@217.153.192.143 Standard REPORTING,
cause: NORMAL_CLEARING
2012-04-11 07:38:28.302060 [DEBUG] switch_core_state_machine.c:599
(sofia/sipinterface_1/7283...@217.153.192.143) State REPORTING going
to sleep
2012-04-11 07:38:28.302060 [DEBUG] switch_core_state_machine.c:331
(sofia/sipinterface_1/7283...@217.153.192.143) State Change
CS_REPORTING -> CS_DESTROY
2012-04-11 07:38:28.302060 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/7283...@217.153.192.143 [BREAK]
2012-04-11 07:38:28.302060 [DEBUG] switch_core_session.c:1224 Session
161 (sofia/sipinterface_1/7283...@217.153.192.143) Locked, Waiting
on external entities
2012-04-11 07:38:28.302060 [NOTICE] switch_core_session.c:1242 Session
161 (sofia/sipinterface_1/7283...@217.153.192.143) Ended
2012-04-11 07:38:28.302060 [NOTICE] switch_core_session.c:1244 Close
Channel sofia/sipinterface_1/7283...@217.153.192.143 [CS_DESTROY]
2012-04-11 07:38:28.302060 [DEBUG] switch_core_state_machine.c:431
(sofia/sipinterface_1/7283...@217.153.192.143) Callstate Change
HANGUP -> DOWN
2012-04-11 07:38:28.302060 [DEBUG] switch_core_state_machine.c:434
(sofia/sipinterface_1/7283...@217.153.192.143) Running State Change
CS_DESTROY
2012-04-11 07:38:28.302060 [DEBUG] switch_core_state_machine.c:444
(sofia/sipinterface_1/7283...@217.153.192.143) State DESTROY
2012-04-11 07:38:28.302060 [DEBUG] mod_sofia.c:361 sofia/
sipinterface_1/7283...@217.153.192.143 SOFIA DESTROY
2012-04-11 07:38:28.302060 [DEBUG] switch_core_state_machine.c:60
sofia/sipinterface_1/7283...@217.153.192.143 Standard DESTROY
2012-04-11 07:38:28.302060 [DEBUG] switch_core_state_machine.c:444
(sofia/sipinterface_1/7283...@217.153.192.143) State DESTROY going
to sleep

outgoing for 587412762:

freeswitch@internal> 2012-04-11 07:44:33.093601 [DEBUG] sofia.c:6237
IP 192.168.1.119 Approved by acl "net_list_5[]". Access Granted.
2012-04-11 07:44:33.093601 [NOTICE] switch_channel.c:784 New Channel
sofia/sipinterface_1/michael...@83.238.41.104 [b1958154-ffe6-4c9f-
bf24-c27b58bb1254]
2012-04-11 07:44:33.095604 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/michael...@83.238.41.104) Running State
Change CS_NEW
2012-04-11 07:44:33.095604 [DEBUG] switch_core_state_machine.c:324
(sofia/sipinterface_1/michael...@83.238.41.104) State NEW
2012-04-11 07:44:33.337591 [DEBUG] sofia.c:7111 Setting NAT mode based
on rfc1918.auto
2012-04-11 07:44:33.337591 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/michael...@83.238.41.104 entering state [received]
[100]
2012-04-11 07:44:33.337591 [DEBUG] sofia.c:4570 Remote SDP:
v=0
o=michael_bolton 8000 8000 IN IP4 192.168.1.119
s=SIP Call
c=IN IP4 192.168.1.119
t=0 0
m=audio 5004 RTP/AVP 9 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2012-04-11 07:44:33.337591 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [G722:9:8000:20:64000]/[G7221:115:32000:20:48000]
2012-04-11 07:44:33.337591 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [G722:9:8000:20:64000]/[G7221:107:16000:20:32000]
2012-04-11 07:44:33.337591 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [G722:9:8000:20:64000]/[G722:9:8000:20:64000]
2012-04-11 07:44:33.337591 [DEBUG] sofia_glue.c:2721 Set Codec sofia/
sipinterface_1/michael...@83.238.41.104 G722/8000 20 ms 160
samples 64000 bits
2012-04-11 07:44:33.337591 [DEBUG] sofia_glue.c:4457 Set 2833 dtmf
send/recv payload to 101
2012-04-11 07:44:33.337591 [DEBUG] sofia.c:4732 (sofia/sipinterface_1/
michael...@83.238.41.104) State Change CS_NEW -> CS_INIT
2012-04-11 07:44:33.337591 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/michael...@83.238.41.104 [BREAK]
2012-04-11 07:44:33.339595 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/michael...@83.238.41.104) Running State
Change CS_INIT
2012-04-11 07:44:33.339595 [DEBUG] switch_core_state_machine.c:342
(sofia/sipinterface_1/michael...@83.238.41.104) State INIT
2012-04-11 07:44:33.339595 [DEBUG] mod_sofia.c:83 sofia/sipinterface_1/
michael...@83.238.41.104 SOFIA INIT
2012-04-11 07:44:33.339595 [DEBUG] mod_sofia.c:123 (sofia/
sipinterface_1/michael...@83.238.41.104) State Change CS_INIT ->
CS_ROUTING
2012-04-11 07:44:33.339595 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/michael...@83.238.41.104 [BREAK]
2012-04-11 07:44:33.339595 [DEBUG] switch_core_state_machine.c:342
(sofia/sipinterface_1/michael...@83.238.41.104) State INIT going
to sleep
2012-04-11 07:44:33.339595 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/michael...@83.238.41.104) Running State
Change CS_ROUTING
2012-04-11 07:44:33.339595 [DEBUG] switch_channel.c:1615 (sofia/
sipinterface_1/michael...@83.238.41.104) Callstate Change DOWN ->
RINGING
2012-04-11 07:44:33.339595 [DEBUG] switch_core_state_machine.c:345
(sofia/sipinterface_1/michael...@83.238.41.104) State ROUTING
2012-04-11 07:44:33.339595 [DEBUG] mod_sofia.c:146 sofia/
sipinterface_1/michael...@83.238.41.104 SOFIA ROUTING
2012-04-11 07:44:33.339595 [DEBUG] switch_core_state_machine.c:77
sofia/sipinterface_1/michael...@83.238.41.104 Standard ROUTING
2012-04-11 07:44:33.339595 [INFO] mod_dialplan_xml.c:331 Processing
michael_bolton <michael_bolton>->224444444 in context context_2
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 parsing
[context_2->conditioning_callrecord] continue=true
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Absolute
Condition [conditioning_callrecord]
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
set(RECORD_TITLE=Recording ${destination_number} ${caller_id_number} $
{strftime(%Y-%m-%d %H:%M)})
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
set(RECORD_COPYRIGHT=(c) 2010 VoIP, Inc.)
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
set(RECORD_SOFTWARE=blue.box)
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
set(RECORD_ARTIST=2600hz)
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
set(RECORD_COMMENT=Automatically recorded via FreeSWITCH with
blue.box)
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
set(RECORD_DATE=${strftime(%Y-%m-%d %H:%M)})
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
set(RECORD_STEREO=true)
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 parsing
[context_2->conditioning_callerid] continue=true
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Regex
(FAIL) [conditioning_callerid] ${internal_caller_id_number}() =~ /^.+
$/ break=on-false
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 parsing
[context_2->postroute_global] continue=true
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Absolute
Condition [postroute_global]
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
hash(insert/${domain_name}-last_dial/${caller_id_number}/$
{destination_number})
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 parsing
[context_2->preanswer_callrecord_outbound] continue=true
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Regex
(FAIL) [preanswer_callrecord_outbound] ${callrecord_outbound}() =~ /^.+
$/ break=on-false
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 parsing
[context_2->main_trunk_4_pattern_5] continue=true
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Regex
(PASS) [main_trunk_4_pattern_5] destination_number(224444444) =~ /
^(\d{9})$/ break=on-false
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
set(prepend=)
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
set(effective_caller_id_name=587412762)
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
set(effective_caller_id_number=587412762)
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Regex
(FAIL) [main_trunk_4_pattern_5] ${outbound_caller_id_number}() =~ /^.+
$/ break=never
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Regex
(PASS) [main_trunk_4_pattern_5] destination_number(224444444) =~ /
^(\d{9})$/ break=on-false
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
bridge(sofia/gateway/trunk_4/${prepend}224444444)
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 parsing
[context_2->main_number_14] continue=true
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Regex
(FAIL) [main_number_14] destination_number(224444444) =~ /^587412762$/
break=on-false
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 parsing
[context_2->main_trunk_1_pattern_5] continue=true
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Regex
(PASS) [main_trunk_1_pattern_5] destination_number(224444444) =~ /
^(\d{9})$/ break=on-false
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
set(prepend=)
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
set(effective_caller_id_name=587412757)
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
set(effective_caller_id_number=587412757)
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Regex
(FAIL) [main_trunk_1_pattern_5] ${outbound_caller_id_number}() =~ /^.+
$/ break=never
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Regex
(PASS) [main_trunk_1_pattern_5] destination_number(224444444) =~ /
^(\d{9})$/ break=on-false
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Action
bridge(sofia/gateway/trunk_1/${prepend}224444444)
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 parsing
[context_2->main_number_11] continue=true
Dialplan: sofia/sipinterface_1/michael...@83.238.41.104 Regex
(FAIL) [main_number_11] destination_number(224444444) =~ /^587412757$/
break=on-false
2012-04-11 07:44:33.339595 [DEBUG] switch_core_state_machine.c:119
(sofia/sipinterface_1/michael...@83.238.41.104) State Change
CS_ROUTING -> CS_EXECUTE
2012-04-11 07:44:33.339595 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/michael...@83.238.41.104 [BREAK]
2012-04-11 07:44:33.339595 [DEBUG] switch_core_state_machine.c:345
(sofia/sipinterface_1/michael...@83.238.41.104) State ROUTING
going to sleep
2012-04-11 07:44:33.339595 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/michael...@83.238.41.104) Running State
Change CS_EXECUTE
2012-04-11 07:44:33.339595 [DEBUG] switch_core_state_machine.c:352
(sofia/sipinterface_1/michael...@83.238.41.104) State EXECUTE
2012-04-11 07:44:33.339595 [DEBUG] mod_sofia.c:239 sofia/
sipinterface_1/michael...@83.238.41.104 SOFIA EXECUTE
2012-04-11 07:44:33.339595 [DEBUG] switch_core_state_machine.c:157
sofia/sipinterface_1/michael...@83.238.41.104 Standard EXECUTE
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104
set(RECORD_TITLE=Recording 224444444 michael_bolton 2012-04-11 07:44)
2012-04-11 07:44:33.339595 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/michael...@83.238.41.104 SET
[RECORD_TITLE]=[Recording 224444444 michael_bolton 2012-04-11 07:44]
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104
set(RECORD_COPYRIGHT=(c) 2010 VoIP, Inc.)
2012-04-11 07:44:33.339595 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/michael...@83.238.41.104 SET
[RECORD_COPYRIGHT]=[(c) 2010 VoIP, Inc.]
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104
set(RECORD_SOFTWARE=blue.box)
2012-04-11 07:44:33.339595 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/michael...@83.238.41.104 SET
[RECORD_SOFTWARE]=[blue.box]
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104
set(RECORD_ARTIST=2600hz)
2012-04-11 07:44:33.341815 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/michael...@83.238.41.104 SET
[RECORD_ARTIST]=[2600hz]
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104
set(RECORD_COMMENT=Automatically recorded via FreeSWITCH with
blue.box)
2012-04-11 07:44:33.341815 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/michael...@83.238.41.104 SET
[RECORD_COMMENT]=[Automatically recorded via FreeSWITCH with blue.box]
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104
set(RECORD_DATE=2012-04-11 07:44)
2012-04-11 07:44:33.341815 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/michael...@83.238.41.104 SET
[RECORD_DATE]=[2012-04-11 07:44]
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104
set(RECORD_STEREO=true)
2012-04-11 07:44:33.341815 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/michael...@83.238.41.104 SET [RECORD_STEREO]=[true]
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104 hash(insert/
127.0.0.1-spymap/michael_bolton/b1958154-ffe6-4c9f-bf24-c27b58bb1254)
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104 hash(insert/
127.0.0.1-last_dial/michael_bolton/224444444)
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104 hash(insert/
127.0.0.1-last_dial/global/b1958154-ffe6-4c9f-bf24-c27b58bb1254)
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104
set(RFC2822_DATE=Wed, 11 Apr 2012 07:44:33 -0700)
2012-04-11 07:44:33.343591 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/michael...@83.238.41.104 SET [RFC2822_DATE]=[Wed,
11 Apr 2012 07:44:33 -0700]
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104
set(prepend=)
2012-04-11 07:44:33.343591 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/michael...@83.238.41.104 SET [prepend]=[UNDEF]
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104
set(effective_caller_id_name=587412762)
2012-04-11 07:44:33.343591 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/michael...@83.238.41.104 SET
[effective_caller_id_name]=[587412762]
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104
set(effective_caller_id_number=587412762)
2012-04-11 07:44:33.343591 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/michael...@83.238.41.104 SET
[effective_caller_id_number]=[587412762]
EXECUTE sofia/sipinterface_1/michael...@83.238.41.104 bridge(sofia/
gateway/trunk_4/224444444)
2012-04-11 07:44:33.343591 [NOTICE] switch_channel.c:784 New Channel
sofia/sipinterface_1/224444444 [2f3381df-5b40-4b3a-8e42-d20ff3d1dcb3]
2012-04-11 07:44:33.467595 [DEBUG] mod_sofia.c:3968 (sofia/
sipinterface_1/224444444) State Change CS_NEW -> CS_INIT
2012-04-11 07:44:33.467595 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:44:33.467595 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/224444444) Running State Change CS_INIT
2012-04-11 07:44:33.467595 [DEBUG] switch_core_state_machine.c:342
(sofia/sipinterface_1/224444444) State INIT
2012-04-11 07:44:33.467595 [DEBUG] mod_sofia.c:83 sofia/
sipinterface_1/224444444 SOFIA INIT
2012-04-11 07:44:33.467595 [DEBUG] mod_sofia.c:123 (sofia/
sipinterface_1/224444444) State Change CS_INIT -> CS_ROUTING
2012-04-11 07:44:33.467595 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:44:33.467595 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/224444444 entering state [calling][0]
2012-04-11 07:44:33.467595 [DEBUG] switch_core_state_machine.c:342
(sofia/sipinterface_1/224444444) State INIT going to sleep
2012-04-11 07:44:33.467595 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/224444444) Running State Change CS_ROUTING
2012-04-11 07:44:33.467595 [DEBUG] switch_channel.c:1615 (sofia/
sipinterface_1/224444444) Callstate Change DOWN -> RINGING
2012-04-11 07:44:33.469605 [DEBUG] switch_core_state_machine.c:345
(sofia/sipinterface_1/224444444) State ROUTING
2012-04-11 07:44:33.469605 [DEBUG] mod_sofia.c:146 sofia/
sipinterface_1/224444444 SOFIA ROUTING
2012-04-11 07:44:33.469605 [DEBUG] switch_ivr_originate.c:66 (sofia/
sipinterface_1/224444444) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2012-04-11 07:44:33.469605 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:44:33.469605 [DEBUG] switch_core_state_machine.c:345
(sofia/sipinterface_1/224444444) State ROUTING going to sleep
2012-04-11 07:44:33.469605 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/224444444) Running State Change CS_CONSUME_MEDIA
2012-04-11 07:44:33.469605 [DEBUG] switch_core_state_machine.c:364
(sofia/sipinterface_1/224444444) State CONSUME_MEDIA
2012-04-11 07:44:33.469605 [DEBUG] switch_core_state_machine.c:364
(sofia/sipinterface_1/224444444) State CONSUME_MEDIA going to sleep
2012-04-11 07:44:33.479601 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/224444444 entering state [calling][0]
2012-04-11 07:44:34.823545 [INFO] sofia.c:709 sofia/
sipinterface_1/224444444 Update Callee ID to "224444444" <224444444>
2012-04-11 07:44:35.053535 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/224444444 entering state [proceeding][183]
2012-04-11 07:44:35.053535 [DEBUG] sofia.c:4570 Remote SDP:
v=0
o=FreeSWITCH 7267539444938069583 5198376087676180396 IN IP4
217.153.192.143
s=FreeSWITCH
c=IN IP4 217.153.192.143
t=0 0
m=audio 13086 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

2012-04-11 07:44:35.053535 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000]
2012-04-11 07:44:35.053535 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMU:0:8000:20:64000]/[G7221:115:32000:20:48000]
2012-04-11 07:44:35.053535 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMU:0:8000:20:64000]/[G7221:107:16000:20:32000]
2012-04-11 07:44:35.053535 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000]
2012-04-11 07:44:35.053535 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2012-04-11 07:44:35.053535 [DEBUG] sofia_glue.c:2721 Set Codec sofia/
sipinterface_1/224444444 PCMU/8000 20 ms 160 samples 64000 bits
2012-04-11 07:44:35.055645 [DEBUG] sofia_glue.c:4451 Set 2833 dtmf
send payload to 101
2012-04-11 07:44:35.055645 [DEBUG] sofia_glue.c:2961 AUDIO RTP [sofia/
sipinterface_1/224444444] 83.238.41.104 port 31374 -> 217.153.192.143
port 13086 codec: 0 ms: 20
2012-04-11 07:44:35.055645 [DEBUG] switch_rtp.c:1418 Starting timer
[soft] 160 bytes per 20ms
2012-04-11 07:44:35.057564 [DEBUG] sofia_glue.c:3179 Set 2833 dtmf
send payload to 101
2012-04-11 07:44:35.057564 [DEBUG] sofia_glue.c:3184 Set 2833 dtmf
receive payload to 101
2012-04-11 07:44:35.057564 [DEBUG] sofia_glue.c:3195 Set comfort noise
payload to 13
2012-04-11 07:44:35.057564 [NOTICE] sofia_glue.c:3591 Pre-Answer sofia/
sipinterface_1/224444444!
2012-04-11 07:44:35.057564 [DEBUG] switch_channel.c:2544 (sofia/
sipinterface_1/224444444) Callstate Change RINGING -> EARLY
2012-04-11 07:44:35.057564 [DEBUG] switch_channel.c:2588 Send signal
sofia/sipinterface_1/michael...@83.238.41.104 [BREAK]
2012-04-11 07:44:35.187530 [INFO] switch_ivr_originate.c:3290 Sending
early media
2012-04-11 07:44:35.187530 [DEBUG] sofia_glue.c:2961 AUDIO RTP [sofia/
sipinterface_1/michael...@83.238.41.104] 83.238.41.104 port 27680 -
> 192.168.1.119 port 5004 codec: 9 ms: 20
2012-04-11 07:44:35.187530 [DEBUG] switch_rtp.c:1418 Starting timer
[soft] 160 bytes per 20ms
2012-04-11 07:44:35.191532 [DEBUG] sofia_glue.c:3179 Set 2833 dtmf
send payload to 101
2012-04-11 07:44:35.191532 [DEBUG] sofia_glue.c:3184 Set 2833 dtmf
receive payload to 101
2012-04-11 07:44:35.191532 [DEBUG] mod_sofia.c:2169 Ring SDP:
v=0
o=FreeSWITCH 1334127795 1334127796 IN IP4 83.238.41.104
s=FreeSWITCH
c=IN IP4 83.238.41.104
t=0 0
m=audio 27680 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2012-04-11 07:44:35.191532 [NOTICE] mod_sofia.c:2172 Pre-Answer sofia/
sipinterface_1/michael...@83.238.41.104!
2012-04-11 07:44:35.191532 [DEBUG] switch_channel.c:2544 (sofia/
sipinterface_1/michael...@83.238.41.104) Callstate Change RINGING -
> EARLY
2012-04-11 07:44:35.191532 [DEBUG] switch_core_session.c:676 Send
signal sofia/sipinterface_1/michael...@83.238.41.104 [BREAK]
2012-04-11 07:44:35.191532 [DEBUG] switch_ivr_originate.c:3333
Originate Resulted in Success: [sofia/sipinterface_1/224444444]
2012-04-11 07:44:35.191532 [DEBUG] switch_core_session.c:676 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:44:35.191532 [DEBUG] switch_core_session.c:676 Send
signal sofia/sipinterface_1/michael...@83.238.41.104 [BREAK]
2012-04-11 07:44:35.191532 [DEBUG] switch_ivr_bridge.c:1226 (sofia/
sipinterface_1/224444444) State Change CS_CONSUME_MEDIA ->
CS_EXCHANGE_MEDIA
2012-04-11 07:44:35.191532 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:44:35.191532 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/224444444) Running State Change
CS_EXCHANGE_MEDIA
2012-04-11 07:44:35.191532 [DEBUG] switch_core_state_machine.c:355
(sofia/sipinterface_1/224444444) State EXCHANGE_MEDIA
2012-04-11 07:44:35.191532 [DEBUG] mod_sofia.c:551 SOFIA
EXCHANGE_MEDIA
2012-04-11 07:44:35.191532 [DEBUG] sofia.c:4554 Channel sofia/
sipinterface_1/michael...@83.238.41.104 skipping state [early]
[183]
2012-04-11 07:44:35.229536 [DEBUG] switch_rtp.c:2544 Correct ip/port
confirmed.
2012-04-11 07:44:35.249533 [DEBUG] switch_rtp.c:2544 Correct ip/port
confirmed.
2012-04-11 07:44:35.771507 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/224444444 entering state [completing][200]
2012-04-11 07:44:35.771507 [DEBUG] sofia.c:4567 Duplicate SDP
v=0
o=FreeSWITCH 7267539444938069583 5198376087676180396 IN IP4
217.153.192.143
s=FreeSWITCH
c=IN IP4 217.153.192.143
t=0 0
m=audio 13086 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

2012-04-11 07:44:35.771507 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/224444444 entering state [ready][200]
2012-04-11 07:44:35.771507 [DEBUG] switch_channel.c:2694 (sofia/
sipinterface_1/224444444) Callstate Change EARLY -> ACTIVE
2012-04-11 07:44:35.771507 [DEBUG] switch_channel.c:2706 Send signal
sofia/sipinterface_1/michael...@83.238.41.104 [BREAK]
2012-04-11 07:44:35.771507 [NOTICE] sofia.c:5083 Channel [sofia/
sipinterface_1/224444444] has been answered
2012-04-11 07:44:35.891503 [DEBUG] mod_sofia.c:680 Local SDP sofia/
sipinterface_1/michael...@83.238.41.104:
v=0
o=FreeSWITCH 1334127795 1334127797 IN IP4 83.238.41.104
s=FreeSWITCH
c=IN IP4 83.238.41.104
t=0 0
m=audio 27680 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2012-04-11 07:44:35.893540 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/michael...@83.238.41.104 entering state [completed]
[200]
2012-04-11 07:44:35.893540 [DEBUG] switch_core_session.c:676 Send
signal sofia/sipinterface_1/michael...@83.238.41.104 [BREAK]
2012-04-11 07:44:35.893540 [DEBUG] switch_channel.c:2694 (sofia/
sipinterface_1/michael...@83.238.41.104) Callstate Change EARLY ->
ACTIVE
2012-04-11 07:44:35.893540 [NOTICE] switch_ivr_bridge.c:398 Channel
[sofia/sipinterface_1/michael...@83.238.41.104] has been answered
2012-04-11 07:44:35.911503 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/michael...@83.238.41.104 entering state [ready]
[200]
2012-04-11 07:44:35.929511 [DEBUG] switch_core_session.c:738 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:44:35.929511 [DEBUG] switch_core_session.c:738 Send
signal sofia/sipinterface_1/michael...@83.238.41.104 [BREAK]
2012-04-11 07:45:01.295489 [DEBUG] switch_channel.c:2457 (sofia/
sipinterface_1/michael...@83.238.41.104) Callstate Change ACTIVE -
> HANGUP
2012-04-11 07:45:01.295489 [NOTICE] sofia.c:528 Hangup sofia/
sipinterface_1/michael...@83.238.41.104 [CS_EXECUTE]
[NORMAL_CLEARING]
2012-04-11 07:45:01.296491 [DEBUG] switch_channel.c:2473 Send signal
sofia/sipinterface_1/michael...@83.238.41.104 [KILL]
2012-04-11 07:45:01.296491 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/michael...@83.238.41.104 [BREAK]
2012-04-11 07:45:01.308488 [DEBUG] switch_ivr_bridge.c:483 sofia/
sipinterface_1/michael...@83.238.41.104 ending bridge by request
from read function
2012-04-11 07:45:01.308488 [DEBUG] switch_ivr_bridge.c:477 sofia/
sipinterface_1/michael...@83.238.41.104 ending bridge by request
from write function
2012-04-11 07:45:01.308488 [DEBUG] switch_ivr_bridge.c:564 BRIDGE
THREAD DONE [sofia/sipinterface_1/michael...@83.238.41.104]
2012-04-11 07:45:01.308488 [DEBUG] switch_ivr_bridge.c:564 BRIDGE
THREAD DONE [sofia/sipinterface_1/224444444]
2012-04-11 07:45:01.308488 [DEBUG] switch_ivr_bridge.c:584 Send signal
sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:45:01.308488 [DEBUG] switch_ivr_bridge.c:584 Send signal
sofia/sipinterface_1/michael...@83.238.41.104 [BREAK]
2012-04-11 07:45:01.308488 [DEBUG] switch_channel.c:2457 (sofia/
sipinterface_1/224444444) Callstate Change ACTIVE -> HANGUP
2012-04-11 07:45:01.308488 [NOTICE] switch_ivr_bridge.c:636 Hangup
sofia/sipinterface_1/224444444 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2012-04-11 07:45:01.308488 [DEBUG] switch_channel.c:2473 Send signal
sofia/sipinterface_1/224444444 [KILL]
2012-04-11 07:45:01.308488 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:45:01.308488 [DEBUG] switch_core_state_machine.c:355
(sofia/sipinterface_1/224444444) State EXCHANGE_MEDIA going to sleep
2012-04-11 07:45:01.308488 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/224444444) Running State Change CS_HANGUP
2012-04-11 07:45:01.308488 [DEBUG] switch_core_state_machine.c:539
(sofia/sipinterface_1/224444444) State HANGUP
2012-04-11 07:45:01.308488 [DEBUG] mod_sofia.c:450 sofia/
sipinterface_1/224444444 Overriding SIP cause 480 with 200 from the
other leg
2012-04-11 07:45:01.308488 [DEBUG] mod_sofia.c:456 Channel sofia/
sipinterface_1/224444444 hanging up, cause: NORMAL_CLEARING
2012-04-11 07:45:01.308488 [DEBUG] switch_ivr_bridge.c:1297 sofia/
sipinterface_1/224444444 skip receive message [UNBRIDGE] (channel is
hungup already)
2012-04-11 07:45:01.308488 [DEBUG] switch_ivr_bridge.c:1300 sofia/
sipinterface_1/michael...@83.238.41.104 skip receive message
[UNBRIDGE] (channel is hungup already)
2012-04-11 07:45:01.308488 [DEBUG] switch_core_session.c:1933 sofia/
sipinterface_1/michael...@83.238.41.104 skip receive message
[APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2012-04-11 07:45:01.308488 [DEBUG] switch_core_state_machine.c:352
(sofia/sipinterface_1/michael...@83.238.41.104) State EXECUTE
going to sleep
2012-04-11 07:45:01.308488 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/michael...@83.238.41.104) Running State
Change CS_HANGUP
2012-04-11 07:45:01.308488 [DEBUG] switch_core_state_machine.c:539
(sofia/sipinterface_1/michael...@83.238.41.104) State HANGUP
2012-04-11 07:45:01.308488 [DEBUG] mod_sofia.c:450 sofia/
sipinterface_1/michael...@83.238.41.104 Overriding SIP cause 480
with 200 from the other leg
2012-04-11 07:45:01.308488 [DEBUG] mod_sofia.c:456 Channel sofia/
sipinterface_1/michael...@83.238.41.104 hanging up, cause:
NORMAL_CLEARING
2012-04-11 07:45:01.573695 [DEBUG] mod_sofia.c:499 Sending BYE to
sofia/sipinterface_1/224444444
2012-04-11 07:45:01.573695 [DEBUG] switch_core_state_machine.c:46
sofia/sipinterface_1/224444444 Standard HANGUP, cause: NORMAL_CLEARING
2012-04-11 07:45:01.573695 [DEBUG] switch_core_state_machine.c:539
(sofia/sipinterface_1/224444444) State HANGUP going to sleep
2012-04-11 07:45:01.573695 [DEBUG] switch_core_state_machine.c:337
(sofia/sipinterface_1/224444444) State Change CS_HANGUP ->
CS_REPORTING
2012-04-11 07:45:01.573695 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:45:01.573695 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/224444444) Running State Change CS_REPORTING
2012-04-11 07:45:01.573695 [DEBUG] switch_core_state_machine.c:599
(sofia/sipinterface_1/224444444) State REPORTING
2012-04-11 07:45:01.573695 [DEBUG] switch_core_state_machine.c:53
sofia/sipinterface_1/224444444 Standard REPORTING, cause:
NORMAL_CLEARING
2012-04-11 07:45:01.573695 [DEBUG] switch_core_state_machine.c:599
(sofia/sipinterface_1/224444444) State REPORTING going to sleep
2012-04-11 07:45:01.574632 [DEBUG] switch_core_state_machine.c:331
(sofia/sipinterface_1/224444444) State Change CS_REPORTING ->
CS_DESTROY
2012-04-11 07:45:01.574632 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/224444444 [BREAK]
2012-04-11 07:45:01.574632 [DEBUG] switch_core_session.c:1224 Session
173 (sofia/sipinterface_1/224444444) Locked, Waiting on external
entities
2012-04-11 07:45:01.574632 [NOTICE] switch_core_session.c:1242 Session
173 (sofia/sipinterface_1/224444444) Ended
2012-04-11 07:45:01.574632 [NOTICE] switch_core_session.c:1244 Close
Channel sofia/sipinterface_1/224444444 [CS_DESTROY]
2012-04-11 07:45:01.574632 [DEBUG] switch_core_state_machine.c:431
(sofia/sipinterface_1/224444444) Callstate Change HANGUP -> DOWN
2012-04-11 07:45:01.574632 [DEBUG] switch_core_state_machine.c:434
(sofia/sipinterface_1/224444444) Running State Change CS_DESTROY
2012-04-11 07:45:01.574632 [DEBUG] switch_core_state_machine.c:444
(sofia/sipinterface_1/224444444) State DESTROY
2012-04-11 07:45:01.575553 [DEBUG] mod_sofia.c:361 sofia/
sipinterface_1/224444444 SOFIA DESTROY
2012-04-11 07:45:01.575553 [DEBUG] switch_core_state_machine.c:60
sofia/sipinterface_1/224444444 Standard DESTROY
2012-04-11 07:45:01.575553 [DEBUG] switch_core_state_machine.c:444
(sofia/sipinterface_1/224444444) State DESTROY going to sleep
2012-04-11 07:45:01.685472 [DEBUG] switch_core_state_machine.c:46
sofia/sipinterface_1/michael...@83.238.41.104 Standard HANGUP,
cause: NORMAL_CLEARING
2012-04-11 07:45:01.685472 [DEBUG] switch_core_state_machine.c:539
(sofia/sipinterface_1/michael...@83.238.41.104) State HANGUP going
to sleep
2012-04-11 07:45:01.685472 [DEBUG] switch_core_state_machine.c:337
(sofia/sipinterface_1/michael...@83.238.41.104) State Change
CS_HANGUP -> CS_REPORTING
2012-04-11 07:45:01.685472 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/michael...@83.238.41.104 [BREAK]
2012-04-11 07:45:01.685472 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/michael...@83.238.41.104) Running State
Change CS_REPORTING
2012-04-11 07:45:01.685472 [DEBUG] switch_core_state_machine.c:599
(sofia/sipinterface_1/michael...@83.238.41.104) State REPORTING
2012-04-11 07:45:01.685472 [DEBUG] switch_core_state_machine.c:53
sofia/sipinterface_1/michael...@83.238.41.104 Standard REPORTING,
cause: NORMAL_CLEARING
2012-04-11 07:45:01.685472 [DEBUG] switch_core_state_machine.c:599
(sofia/sipinterface_1/michael...@83.238.41.104) State REPORTING
going to sleep
2012-04-11 07:45:01.686829 [DEBUG] switch_core_state_machine.c:331
(sofia/sipinterface_1/michael...@83.238.41.104) State Change
CS_REPORTING -> CS_DESTROY
2012-04-11 07:45:01.686829 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/michael...@83.238.41.104 [BREAK]
2012-04-11 07:45:01.686829 [DEBUG] switch_core_session.c:1224 Session
172 (sofia/sipinterface_1/michael...@83.238.41.104) Locked,
Waiting on external entities
2012-04-11 07:45:01.686829 [NOTICE] switch_core_session.c:1242 Session
172 (sofia/sipinterface_1/michael...@83.238.41.104) Ended
2012-04-11 07:45:01.686829 [NOTICE] switch_core_session.c:1244 Close
Channel sofia/sipinterface_1/michael...@83.238.41.104 [CS_DESTROY]
2012-04-11 07:45:01.686829 [DEBUG] switch_core_state_machine.c:431
(sofia/sipinterface_1/michael...@83.238.41.104) Callstate Change
HANGUP -> DOWN
2012-04-11 07:45:01.686829 [DEBUG] switch_core_state_machine.c:434
(sofia/sipinterface_1/michael...@83.238.41.104) Running State
Change CS_DESTROY
2012-04-11 07:45:01.686829 [DEBUG] switch_core_state_machine.c:444
(sofia/sipinterface_1/michael...@83.238.41.104) State DESTROY
2012-04-11 07:45:01.686829 [DEBUG] mod_sofia.c:361 sofia/
sipinterface_1/michael...@83.238.41.104 SOFIA DESTROY
2012-04-11 07:45:01.686829 [DEBUG] switch_core_state_machine.c:60
sofia/sipinterface_1/michael...@83.238.41.104 Standard DESTROY
2012-04-11 07:45:01.686829 [DEBUG] switch_core_state_machine.c:444
(sofia/sipinterface_1/michael...@83.238.41.104) State DESTROY
going to sleep

incoming fo 587412762:

freeswitch@internal> 2012-04-11 07:43:47.553403 [DEBUG] sofia.c:6237
IP 217.153.192.153 Approved by acl "net_list_5[]". Access Granted.
2012-04-11 07:43:47.553403 [NOTICE] switch_channel.c:784 New Channel
sofia/sipinterface_1/7283...@217.153.192.143 [3f7bc11f-2726-4722-
bb34-ae52184a1214]
2012-04-11 07:43:47.554405 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/7283...@217.153.192.143) Running State Change
CS_NEW
2012-04-11 07:43:47.554405 [DEBUG] switch_core_state_machine.c:324
(sofia/sipinterface_1/7283...@217.153.192.143) State NEW
2012-04-11 07:43:47.789394 [DEBUG] sofia.c:4559 Channel sofia/
sipinterface_1/7283...@217.153.192.143 entering state [received]
[100]
2012-04-11 07:43:47.790394 [DEBUG] sofia.c:4570 Remote SDP:
v=0
o=FreeSWITCH 4771871731136731684 3160037191069259372 IN IP4
217.153.192.143
s=FreeSWITCH
c=IN IP4 217.153.192.143
t=0 0
m=audio 11012 RTP/AVP 8 0 2 3 102 18 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:2 AAL2-G726-32/8000
a=rtpmap:3 GSM/8000
a=rtpmap:102 iLBC/8000
a=fmtp:102 mode=30
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20

2012-04-11 07:43:47.790394 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMA:8:8000:20:64000]/[G7221:115:32000:20:48000]
2012-04-11 07:43:47.790394 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMA:8:8000:20:64000]/[G7221:107:16000:20:32000]
2012-04-11 07:43:47.790394 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000]
2012-04-11 07:43:47.790394 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2012-04-11 07:43:47.790394 [DEBUG] sofia_glue.c:4353 Audio Codec
Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2012-04-11 07:43:47.790394 [DEBUG] sofia_glue.c:2721 Set Codec sofia/
sipinterface_1/7283...@217.153.192.143 PCMA/8000 20 ms 160 samples
64000 bits
2012-04-11 07:43:47.790394 [DEBUG] sofia_glue.c:4457 Set 2833 dtmf
send/recv payload to 101
2012-04-11 07:43:47.790394 [DEBUG] sofia.c:4732 (sofia/
sipinterface_1/7283...@217.153.192.143) State Change CS_NEW ->
CS_INIT
2012-04-11 07:43:47.790394 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/7283...@217.153.192.143 [BREAK]
2012-04-11 07:43:47.791400 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/7283...@217.153.192.143) Running State Change
CS_INIT
2012-04-11 07:43:47.791400 [DEBUG] switch_core_state_machine.c:342
(sofia/sipinterface_1/7283...@217.153.192.143) State INIT
2012-04-11 07:43:47.791400 [DEBUG] mod_sofia.c:83 sofia/
sipinterface_1/7283...@217.153.192.143 SOFIA INIT
2012-04-11 07:43:47.791400 [DEBUG] mod_sofia.c:123 (sofia/
sipinterface_1/7283...@217.153.192.143) State Change CS_INIT ->
CS_ROUTING
2012-04-11 07:43:47.791400 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/7283...@217.153.192.143 [BREAK]
2012-04-11 07:43:47.791400 [DEBUG] switch_core_state_machine.c:342
(sofia/sipinterface_1/7283...@217.153.192.143) State INIT going to
sleep
2012-04-11 07:43:47.791400 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/7283...@217.153.192.143) Running State Change
CS_ROUTING
2012-04-11 07:43:47.791400 [DEBUG] switch_channel.c:1615 (sofia/
sipinterface_1/7283...@217.153.192.143) Callstate Change DOWN ->
RINGING
2012-04-11 07:43:47.791400 [DEBUG] switch_core_state_machine.c:345
(sofia/sipinterface_1/7283...@217.153.192.143) State ROUTING
2012-04-11 07:43:47.791400 [DEBUG] mod_sofia.c:146 sofia/
sipinterface_1/7283...@217.153.192.143 SOFIA ROUTING
2012-04-11 07:43:47.791400 [DEBUG] switch_core_state_machine.c:77
sofia/sipinterface_1/7283...@217.153.192.143 Standard ROUTING
2012-04-11 07:43:47.791400 [INFO] mod_dialplan_xml.c:331 Processing
728331224 <728331224>->iqservice015 in context context_2
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->conditioning_callrecord] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Absolute
Condition [conditioning_callrecord]
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RECORD_TITLE=Recording ${destination_number} ${caller_id_number} $
{strftime(%Y-%m-%d %H:%M)})
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RECORD_COPYRIGHT=(c) 2010 VoIP, Inc.)
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RECORD_SOFTWARE=blue.box)
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RECORD_ARTIST=2600hz)
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RECORD_COMMENT=Automatically recorded via FreeSWITCH with
blue.box)
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RECORD_DATE=${strftime(%Y-%m-%d %H:%M)})
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RECORD_STEREO=true)
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->conditioning_callerid] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Regex (FAIL)
[conditioning_callerid] ${internal_caller_id_number}() =~ /^.+$/
break=on-false
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->postroute_global] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Absolute
Condition [postroute_global]
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
hash(insert/${domain_name}-last_dial/${caller_id_number}/$
{destination_number})
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Action
set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->preanswer_callrecord_outbound] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Regex (FAIL)
[preanswer_callrecord_outbound] ${callrecord_outbound}() =~ /^.+$/
break=on-false
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->main_trunk_4_pattern_5] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Regex (FAIL)
[main_trunk_4_pattern_5] destination_number(iqservice015) =~ /^(\d{9})
$/ break=on-false
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->main_number_14] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Regex (FAIL)
[main_number_14] destination_number(iqservice015) =~ /^587412762$/
break=on-false
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->main_trunk_1_pattern_5] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Regex (FAIL)
[main_trunk_1_pattern_5] destination_number(iqservice015) =~ /^(\d{9})
$/ break=on-false
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 parsing
[context_2->main_number_11] continue=true
Dialplan: sofia/sipinterface_1/7283...@217.153.192.143 Regex (FAIL)
[main_number_11] destination_number(iqservice015) =~ /^587412757$/
break=on-false
2012-04-11 07:43:47.792396 [DEBUG] switch_core_state_machine.c:119
(sofia/sipinterface_1/7283...@217.153.192.143) State Change
CS_ROUTING -> CS_EXECUTE
2012-04-11 07:43:47.792396 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/7283...@217.153.192.143 [BREAK]
2012-04-11 07:43:47.792396 [DEBUG] switch_core_state_machine.c:345
(sofia/sipinterface_1/7283...@217.153.192.143) State ROUTING going
to sleep
2012-04-11 07:43:47.792396 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/7283...@217.153.192.143) Running State Change
CS_EXECUTE
2012-04-11 07:43:47.792396 [DEBUG] switch_core_state_machine.c:352
(sofia/sipinterface_1/7283...@217.153.192.143) State EXECUTE
2012-04-11 07:43:47.792396 [DEBUG] mod_sofia.c:239 sofia/
sipinterface_1/7283...@217.153.192.143 SOFIA EXECUTE
2012-04-11 07:43:47.792396 [DEBUG] switch_core_state_machine.c:157
sofia/sipinterface_1/7283...@217.153.192.143 Standard EXECUTE
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RECORD_TITLE=Recording iqservice015 728331224 2012-04-11 07:43)
2012-04-11 07:43:47.792396 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET [RECORD_TITLE]=[Recording
iqservice015 728331224 2012-04-11 07:43]
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RECORD_COPYRIGHT=(c) 2010 VoIP, Inc.)
2012-04-11 07:43:47.792396 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET [RECORD_COPYRIGHT]=[(c)
2010 VoIP, Inc.]
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RECORD_SOFTWARE=blue.box)
2012-04-11 07:43:47.793419 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET
[RECORD_SOFTWARE]=[blue.box]
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RECORD_ARTIST=2600hz)
2012-04-11 07:43:47.793419 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET [RECORD_ARTIST]=[2600hz]
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RECORD_COMMENT=Automatically recorded via FreeSWITCH with
blue.box)
2012-04-11 07:43:47.793419 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET
[RECORD_COMMENT]=[Automatically recorded via FreeSWITCH with blue.box]
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RECORD_DATE=2012-04-11 07:43)
2012-04-11 07:43:47.793419 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET [RECORD_DATE]=[2012-04-11
07:43]
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RECORD_STEREO=true)
2012-04-11 07:43:47.794397 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET [RECORD_STEREO]=[true]
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143 hash(insert/
127.0.0.1-spymap/728331224/3f7bc11f-2726-4722-bb34-ae52184a1214)
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143 hash(insert/
127.0.0.1-last_dial/728331224/iqservice015)
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143 hash(insert/
127.0.0.1-last_dial/global/3f7bc11f-2726-4722-bb34-ae52184a1214)
EXECUTE sofia/sipinterface_1/7283...@217.153.192.143
set(RFC2822_DATE=Wed, 11 Apr 2012 07:43:47 -0700)
2012-04-11 07:43:47.795399 [DEBUG] mod_dptools.c:1028 sofia/
sipinterface_1/7283...@217.153.192.143 SET [RFC2822_DATE]=[Wed, 11
Apr 2012 07:43:47 -0700]
2012-04-11 07:43:47.795399 [NOTICE] switch_core_state_machine.c:189
sofia/sipinterface_1/7283...@217.153.192.143 has executed the last
dialplan instruction, hanging up.
2012-04-11 07:43:47.795399 [DEBUG] switch_channel.c:2457 (sofia/
sipinterface_1/7283...@217.153.192.143) Callstate Change RINGING ->
HANGUP
2012-04-11 07:43:47.795399 [NOTICE] switch_core_state_machine.c:191
Hangup sofia/sipinterface_1/7283...@217.153.192.143 [CS_EXECUTE]
[NORMAL_CLEARING]
2012-04-11 07:43:47.795399 [DEBUG] switch_channel.c:2473 Send signal
sofia/sipinterface_1/7283...@217.153.192.143 [KILL]
2012-04-11 07:43:47.795399 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/7283...@217.153.192.143 [BREAK]
2012-04-11 07:43:47.795399 [DEBUG] switch_core_state_machine.c:352
(sofia/sipinterface_1/7283...@217.153.192.143) State EXECUTE going
to sleep
2012-04-11 07:43:47.795399 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/7283...@217.153.192.143) Running State Change
CS_HANGUP
2012-04-11 07:43:47.796396 [DEBUG] switch_core_state_machine.c:539
(sofia/sipinterface_1/7283...@217.153.192.143) State HANGUP
2012-04-11 07:43:47.796396 [DEBUG] mod_sofia.c:456 Channel sofia/
sipinterface_1/7283...@217.153.192.143 hanging up, cause:
NORMAL_CLEARING
2012-04-11 07:43:47.905393 [DEBUG] mod_sofia.c:518 Responding to
INVITE with: 480
2012-04-11 07:43:47.905393 [DEBUG] switch_core_state_machine.c:46
sofia/sipinterface_1/7283...@217.153.192.143 Standard HANGUP, cause:
NORMAL_CLEARING
2012-04-11 07:43:47.905393 [DEBUG] switch_core_state_machine.c:539
(sofia/sipinterface_1/7283...@217.153.192.143) State HANGUP going to
sleep
2012-04-11 07:43:47.905393 [DEBUG] switch_core_state_machine.c:337
(sofia/sipinterface_1/7283...@217.153.192.143) State Change
CS_HANGUP -> CS_REPORTING
2012-04-11 07:43:47.905393 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/7283...@217.153.192.143 [BREAK]
2012-04-11 07:43:47.905393 [DEBUG] switch_core_state_machine.c:318
(sofia/sipinterface_1/7283...@217.153.192.143) Running State Change
CS_REPORTING
2012-04-11 07:43:47.905393 [DEBUG] switch_core_state_machine.c:599
(sofia/sipinterface_1/7283...@217.153.192.143) State REPORTING
2012-04-11 07:43:47.905393 [DEBUG] switch_core_state_machine.c:53
sofia/sipinterface_1/7283...@217.153.192.143 Standard REPORTING,
cause: NORMAL_CLEARING
2012-04-11 07:43:47.905393 [DEBUG] switch_core_state_machine.c:599
(sofia/sipinterface_1/7283...@217.153.192.143) State REPORTING going
to sleep
2012-04-11 07:43:47.905393 [DEBUG] switch_core_state_machine.c:331
(sofia/sipinterface_1/7283...@217.153.192.143) State Change
CS_REPORTING -> CS_DESTROY
2012-04-11 07:43:47.905393 [DEBUG] switch_core_session.c:1057 Send
signal sofia/sipinterface_1/7283...@217.153.192.143 [BREAK]
2012-04-11 07:43:47.905393 [DEBUG] switch_core_session.c:1224 Session
171 (sofia/sipinterface_1/7283...@217.153.192.143) Locked, Waiting
on external entities
2012-04-11 07:43:47.905393 [NOTICE] switch_core_session.c:1242 Session
171 (sofia/sipinterface_1/7283...@217.153.192.143) Ended
2012-04-11 07:43:47.905393 [NOTICE] switch_core_session.c:1244 Close
Channel sofia/sipinterface_1/7283...@217.153.192.143 [CS_DESTROY]
2012-04-11 07:43:47.905393 [DEBUG] switch_core_state_machine.c:431
(sofia/sipinterface_1/7283...@217.153.192.143) Callstate Change
HANGUP -> DOWN
2012-04-11 07:43:47.905393 [DEBUG] switch_core_state_machine.c:434
(sofia/sipinterface_1/7283...@217.153.192.143) Running State Change
CS_DESTROY
2012-04-11 07:43:47.905393 [DEBUG] switch_core_state_machine.c:444
(sofia/sipinterface_1/7283...@217.153.192.143) State DESTROY
2012-04-11 07:43:47.905393 [DEBUG] mod_sofia.c:361 sofia/
sipinterface_1/7283...@217.153.192.143 SOFIA DESTROY
2012-04-11 07:43:47.905393 [DEBUG] switch_core_state_machine.c:60
sofia/sipinterface_1/7283...@217.153.192.143 Standard DESTROY
2012-04-11 07:43:47.905393 [DEBUG] switch_core_state_machine.c:444
(sofia/sipinterface_1/7283...@217.153.192.143) State DESTROY going
to sleep

[Darren Schreiber]

I'm not 100% sure what you mean by this post (though thanks for all the
data!). Are you trying to make device 2001 use trunk #1 and device 2003
user trunk #2? You mentionstuff about setting caller ID on the trunks, so
I'm not really sure what you're doing, and you haven't mentioned contexts
which, if you are using the same regex, it's going to match on both...

For the inbound call I can't tell which of the logs below is for inbound,
can you just paste them separately or with --------------------- between
them?

--
Darren Schreiber
CEO / Co-Founder

[horiz0n]

On 14 Kwi, 08:28, Darren Schreiber <dar...@2600hz.com> wrote:
> I'm not 100% sure what you mean by this post (though thanks for all the
> data!). Are you trying to make device 2001 use trunk #1 and device 2003
> user trunk #2? You mentionstuff about setting caller ID on the trunks, so
> I'm not really sure what you're doing, and you haven't mentioned contexts
> which, if you are using the same regex, it's going to match on both...
>
> For the inbound call I can't tell which of the logs below is for inbound,
> can you just paste them separately or with --------------------- between
> them?
>
> --
> Darren Schreiber
> CEO / Co-Founder
>

hi, thanks for reply, first:
my sip operator gave me couple of sip accounts:
123456789:pass...@sipserver.com
234567890:pass...@sipserver.com
345678901:pass...@sipserver.com
where: 123456789 etc is phone number.
now, i would like to setup bluebox to make outbound calls with proper
callerID, and working properly inbound calls.
it is not nessesary to have 200x numbers redirected to public phone
numbers.

[Darren Schreiber]

Are you trying to map specific phones to use specific numbers? Or are you
trying to have the outbound calls cycle through all SIP accounts?

--
Darren Schreiber
CEO / Co-Founder

[horiz0n]

On 16 Kwi, 17:12, Darren Schreiber <dar...@2600hz.com> wrote:
> Are you trying to map specific phones to use specific numbers? Or are you
> trying to have the outbound calls cycle through all SIP accounts?
>
> --
> Darren Schreiber
> CEO / Co-Founder
>

i dont know if i understand you, but probably i need to use "specific

[Darren Schreiber]

If you want to map 1:1 a phone to a phone number, you will need to put
each phone into a context of it's own. This is a fairly advanced scenario
actually, but not that hard to do.

First, create three individual contexts.
Then edit each device, put each one in a different context.
Finally, for each SIP trunk, check only one box (different for each) on
the "Made Via These Contexts..." section.

Then you have mapped each device to a separate context.

If you also want inter-office dialing you should additionally edit any
numbers assigned to the devices and mark both their own context and a
general context (like in-house numbers) so they can all call each other.

--
Darren Schreiber
CEO / Co-Founder

[horiz0n]

On 17 Kwi, 17:28, Darren Schreiber <dar...@2600hz.com> wrote:
> If you want to map 1:1 a phone to a phone number, you will need to put
> each phone into a context of it's own. This is a fairly advanced scenario
> actually, but not that hard to do.
>
> First, create three individual contexts.
> Then edit each device, put each one in a different context.
> Finally, for each SIP trunk, check only one box (different for each) on
> the "Made Via These Contexts..." section.
>
> Then you have mapped each device to a separate context.
>
> If you also want inter-office dialing you should additionally edit any
> numbers assigned to the devices and mark both their own context and a
> general context (like in-house numbers) so they can all call each other.
>
> --
> Darren Schreiber
> CEO / Co-Founder
>

> On 4/16/12 11:56 PM, "horiz0n" <kapturkiewiczk1...@gmail.com> wrote:
>
>
>
>
>
>
>
> >On 16 Kwi, 17:12, Darren Schreiber <dar...@2600hz.com> wrote:
> >> Are you trying to map specific phones to use specific numbers? Or are
> >>you
> >> trying to have the outbound calls cycle through all SIP accounts?
>

hi again,
i've created new contexts for each number, then i created new device
with external/public number without any redirections to internal
numbers (like 200x). now i try to call from outside to this number,
but connection is refused.
logs says:
freeswitch@internal> 2012-04-27 08:42:00.431581 [DEBUG] sofia.c:6288
IP 2xx.1xx.1xx.1xx Rejected by acl "rfc1918.auto". Falling back to
Digest auth.
2012-04-27 08:42:00.677572 [DEBUG] sofia.c:6288 IP 2xx.1xx.1xx.1xx
Rejected by acl "rfc1918.auto". Falling back to Digest auth.

2xx.1xx.1xx.1xx - is my sip provider.

all my test devices are in 192.168.1.x network, my BB have only public
IP address but it is the same physical network.

brgds,