Hi,
I have a multi tenant setup with fusionpbx, for one domain I use extensions that don’t register just for voicemail i.e 201@domain1.com , when someone from xx@domain1.com calls 201 everything appears to go correctly, domain is set and call goes to 201@domain1.com but when it first becomes an ip it sends to 201@domain2.ip.address. It doesn’t seem to happen with all extensions numbered the same in different domains..
Any idea what to look for??
Log as follows.
2012-07-26 09:37:35.178096 [NOTICE] switch_channel.c:926 New Channel sofia/internal/306@domain1.com [b62db898-d6b1-11e1-be15-73f389528c7f]
2012-07-26 09:37:35.178096 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/306@domain1.com) Running State Change CS_NEW
2012-07-26 09:37:35.178096 [DEBUG] switch_core_state_machine.c:403 (sofia/internal/306@domain1.com) State NEW
2012-07-26 09:37:35.178096 [DEBUG] sofia.c:5838 Channel sofia/internal/306@domain1.com entering state [received][100]
2012-07-26 09:37:35.178096 [DEBUG] sofia.c:5849 Remote SDP:
v=0
o=- 60255882 60255882 IN IP4 115.64.93.203
s=-
c=IN IP4 115.64.93.203
t=0 0
m=audio 55938 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
2012-07-26 09:37:35.178096 [DEBUG] sofia_glue.c:3941 Looking for zrtp-hash
2012-07-26 09:37:35.178096 [DEBUG] sofia_glue.c:3919 Deciding whether to pass zrtp-hash between legs
2012-07-26 09:37:35.178096 [DEBUG] sofia_glue.c:3921 CF_ZRTP_PASSTHRU_REQ not set, so not propagating zrtp-hash
2012-07-26 09:37:35.178096 [DEBUG] sofia_glue.c:5034 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2012-07-26 09:37:35.178096 [DEBUG] sofia_glue.c:3020 Set Codec sofia/internal/306@domain1.com PCMA/8000 20 ms 160 samples 64000 bits
2012-07-26 09:37:35.178096 [DEBUG] switch_core_codec.c:111 sofia/internal/306@domain1.com Original read codec set to PCMA:8
2012-07-26 09:37:35.178096 [DEBUG] sofia_glue.c:5155 Set 2833 dtmf send/recv payload to 101
2012-07-26 09:37:35.178096 [DEBUG] sofia.c:6077 (sofia/internal/306@domain1.com) State Change CS_NEW -> CS_INIT
2012-07-26 09:37:35.178096 [DEBUG] switch_core_session.c:1228 Send signal sofia/internal/306@domain1.com [BREAK]
2012-07-26 09:37:35.178096 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/306@domain1.com) Running State Change CS_INIT
2012-07-26 09:37:35.178096 [DEBUG] switch_core_state_machine.c:424 (sofia/internal/306@domain1.com) State INIT
2012-07-26 09:37:35.178096 [DEBUG] mod_sofia.c:85 sofia/internal/306@domain1.com SOFIA INIT
2012-07-26 09:37:35.178096 [DEBUG] mod_sofia.c:125 (sofia/internal/306@domain1.com) State Change CS_INIT -> CS_ROUTING
2012-07-26 09:37:35.178096 [DEBUG] switch_core_session.c:1228 Send signal sofia/internal/306@domain1.com [BREAK]
2012-07-26 09:37:35.178096 [DEBUG] switch_core_state_machine.c:424 (sofia/internal/306@domain1.com) State INIT going to sleep
2012-07-26 09:37:35.178096 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/306@domain1.com) Running State Change CS_ROUTING
2012-07-26 09:37:35.178096 [DEBUG] switch_channel.c:1919 (sofia/internal/306@domain1.com) Callstate Change DOWN -> RINGING
2012-07-26 09:37:35.178096 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/306@domain1.com) State ROUTING
2012-07-26 09:37:35.178096 [DEBUG] mod_sofia.c:148 sofia/internal/306@domain1.com SOFIA ROUTING
2012-07-26 09:37:35.178096 [DEBUG] switch_core_state_machine.c:104 sofia/internal/306@domain1.com Standard ROUTING
2012-07-26 09:37:35.178096 [INFO] mod_dialplan_xml.c:485 Processing 0286249343 <306>->201 in context domain1.com
Dialplan: sofia/internal/306@domain1.com parsing [domain1.com->unloop] continue=false
Dialplan: sofia/internal/306@domain1.com parsing [domain1.com->Local_Extension] continue=false
Dialplan: sofia/internal/306@domain1.com Regex (PASS) [Local_Extension] destination_number(201) =~ /(^\d{2,7}$)/ break=on-false
Dialplan: sofia/internal/306@domain1.com Action set(dialed_extension=201)
Dialplan: sofia/internal/306@domain1.com Action export(dialed_extension=201)
Dialplan: sofia/internal/306@domain1.com Action limit(hash ${domain_name} 201 ${limit_max} ${limit_destination})
Dialplan: sofia/internal/306@domain1.com Action bind_meta_app(1 b s execute_extension::dx XML features)
Dialplan: sofia/internal/306@domain1.com Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/archive/${strftime(%Y)}/${strftime(%b)}/${strftime(%d)}/${uuid}.wav)
Dialplan: sofia/internal/306@domain1.com Action bind_meta_app(3 b s execute_extension::cf XML features)
Dialplan: sofia/internal/306@domain1.com Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
Dialplan: sofia/internal/306@domain1.com Action set(ringback=${us-ring})
Dialplan: sofia/internal/306@domain1.com Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/306@domain1.com Action set(call_timeout=30)
Dialplan: sofia/internal/306@domain1.com Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/306@domain1.com Action set(continue_on_fail=true)
Dialplan: sofia/internal/306@domain1.com Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/306@domain1.com Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/306@domain1.com Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
Dialplan: sofia/internal/306@domain1.com Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/306@domain1.com Action bridge(user/${user_data(${destination_number}@${domain_name} attr id)}@${domain_name})
Dialplan: sofia/internal/306@domain1.com Action answer()
Dialplan: sofia/internal/306@domain1.com Action sleep(1000)
Dialplan: sofia/internal/306@domain1.com Action voicemail(default ${domain_name} ${dialed_extension})
2012-07-26 09:37:35.178096 [DEBUG] switch_core_state_machine.c:154 (sofia/internal/306@domain1.com) State Change CS_ROUTING -> CS_EXECUTE
2012-07-26 09:37:35.178096 [DEBUG] switch_core_session.c:1228 Send signal sofia/internal/306@domain1.com [BREAK]
2012-07-26 09:37:35.178096 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/306@domain1.com) State ROUTING going to sleep
2012-07-26 09:37:35.178096 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/306@domain1.com) Running State Change CS_EXECUTE
2012-07-26 09:37:35.178096 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/306@domain1.com) State EXECUTE
2012-07-26 09:37:35.178096 [DEBUG] mod_sofia.c:241 sofia/internal/306@domain1.com SOFIA EXECUTE
2012-07-26 09:37:35.178096 [DEBUG] switch_core_state_machine.c:196 sofia/internal/306@domain1.com Standard EXECUTE
EXECUTE sofia/internal/306@domain1.com set(call_direction=local)
2012-07-26 09:37:35.178096 [DEBUG] mod_dptools.c:1305 sofia/internal/306@domain1.com SET [call_direction]=[local]
EXECUTE sofia/internal/306@domain1.com set(open=true)
2012-07-26 09:37:35.178096 [DEBUG] mod_dptools.c:1305 sofia/internal/306@domain1.com SET [open]=[true]
EXECUTE sofia/internal/306@domain1.com hash(insert/domain1.com-spymap/306/b62db898-d6b1-11e1-be15-73f389528c7f)
EXECUTE sofia/internal/306@domain1.com hash(insert/domain1.com-last_dial/306/201)
EXECUTE sofia/internal/306@domain1.com hash(insert/domain1.com-last_dial/global/b62db898-d6b1-11e1-be15-73f389528c7f)
EXECUTE sofia/internal/306@domain1.com set(RFC2822_DATE=Thu, 26 Jul 2012 09:37:35 +1000)
2012-07-26 09:37:35.178096 [DEBUG] mod_dptools.c:1305 sofia/internal/306@domain1.com SET [RFC2822_DATE]=[Thu, 26 Jul 2012 09:37:35 +1000]
EXECUTE sofia/internal/306@domain1.com set(dialed_extension=201)
2012-07-26 09:37:35.178096 [DEBUG] mod_dptools.c:1305 sofia/internal/306@domain1.com SET [dialed_extension]=[201]
EXECUTE sofia/internal/306@domain1.com export(dialed_extension=201)
2012-07-26 09:37:35.178096 [DEBUG] switch_channel.c:1093 EXPORT (export_vars) [dialed_extension]=[201]
EXECUTE sofia/internal/306@domain1.com limit(hash domain1.com 201 2 !BUSY)
2012-07-26 09:37:35.178096 [INFO] switch_limit.c:126 incr called: domain1.com_201 max:2, interval:0
2012-07-26 09:37:35.178096 [INFO] mod_hash.c:202 Usage for domain1.com_201 is now 1/2
EXECUTE sofia/internal/306@domain1.com bind_meta_app(1 b s execute_extension::dx XML features)
2012-07-26 09:37:35.178096 [INFO] switch_ivr_async.c:3328 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE sofia/internal/306@domain1.com bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/archive/2012/Jul/26/b62db898-d6b1-11e1-be15-73f389528c7f.wav)
2012-07-26 09:37:35.178096 [INFO] switch_ivr_async.c:3328 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/archive/2012/Jul/26/b62db898-d6b1-11e1-be15-73f389528c7f.wav
EXECUTE sofia/internal/306@domain1.com bind_meta_app(3 b s execute_extension::cf XML features)
2012-07-26 09:37:35.178096 [INFO] switch_ivr_async.c:3328 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE sofia/internal/306@domain1.com bind_meta_app(4 b s execute_extension::att_xfer XML features)
2012-07-26 09:37:35.178096 [INFO] switch_ivr_async.c:3328 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE sofia/internal/306@domain1.com set(ringback=%(2000, 4000, 440.0, 480.0))
2012-07-26 09:37:35.178096 [DEBUG] mod_dptools.c:1305 sofia/internal/306@domain1.com SET [ringback]=[%(2000, 4000, 440.0, 480.0)]
EXECUTE sofia/internal/306@domain1.com set(transfer_ringback=local_stream://moh)
2012-07-26 09:37:35.178096 [DEBUG] mod_dptools.c:1305 sofia/internal/306@domain1.com SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/306@domain1.com set(call_timeout=30)
2012-07-26 09:37:35.178096 [DEBUG] mod_dptools.c:1305 sofia/internal/306@domain1.com SET [call_timeout]=[30]
EXECUTE sofia/internal/306@domain1.com set(hangup_after_bridge=true)
2012-07-26 09:37:35.178096 [DEBUG] mod_dptools.c:1305 sofia/internal/306@domain1.com SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/306@domain1.com set(continue_on_fail=true)
2012-07-26 09:37:35.178096 [DEBUG] mod_dptools.c:1305 sofia/internal/306@domain1.com SET [continue_on_fail]=[true]
EXECUTE sofia/internal/306@domain1.com hash(insert/domain1.com-call_return/201/306)
EXECUTE sofia/internal/306@domain1.com hash(insert/domain1.com-last_dial_ext/201/b62db898-d6b1-11e1-be15-73f389528c7f)
EXECUTE sofia/internal/306@domain1.com set(called_party_callgroup=)
2012-07-26 09:37:35.178096 [DEBUG] mod_dptools.c:1305 sofia/internal/306@domain1.com SET [called_party_callgroup]=[UNDEF]
EXECUTE sofia/internal/306@domain1.com hash(insert/domain1.com-last_dial//b62db898-d6b1-11e1-be15-73f389528c7f)
EXECUTE sofia/internal/306@domain1.com bridge(user/201@domain1.com)
2012-07-26 09:37:35.178096 [DEBUG] switch_channel.c:1047 sofia/internal/306@domain1.com EXPORTING[export_vars] [domain_name]=[domain1.com] to event
2012-07-26 09:37:35.178096 [DEBUG] switch_channel.c:1047 sofia/internal/306@domain1.com EXPORTING[export_vars] [dialed_extension]=[201] to event
2012-07-26 09:37:35.178096 [DEBUG] switch_ivr_originate.c:1958 Parsing global variables
2012-07-26 09:37:35.198097 [DEBUG] switch_channel.c:1047 sofia/internal/306@domain1.com EXPORTING[export_vars] [domain_name]=[domain1.com] to event
2012-07-26 09:37:35.198097 [DEBUG] switch_channel.c:1047 sofia/internal/306@domain1.com EXPORTING[export_vars] [dialed_extension]=[201] to event
2012-07-26 09:37:35.198097 [DEBUG] switch_ivr_originate.c:1958 Parsing global variables
2012-07-26 09:37:35.198097 [DEBUG] switch_event.c:1470 Parsing variable [sip_invite_domain]=[domain1.com]
2012-07-26 09:37:35.198097 [DEBUG] switch_event.c:1470 Parsing variable [presence_id]=[201@domain1.com]
2012-07-26 09:37:35.198097 [NOTICE] switch_channel.c:926 New Channel sofia/internal/sip:201@110.143.31.101:1178 [b630218c-d6b1-11e1-be1d-73f389528c7f]
2012-07-26 09:37:35.198097 [DEBUG] mod_sofia.c:4734 (sofia/internal/sip:201@110.143.31.101:1178) State Change CS_NEW -> CS_INIT
2012-07-26 09:37:35.198097 [DEBUG] switch_core_session.c:1228 Send signal sofia/internal/sip:201@110.143.31.101:1178 [BREAK]
2012-07-26 09:37:35.198097 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:201@110.143.31.101:1178) Running State Change CS_INIT
2012-07-26 09:37:35.198097 [DEBUG] switch_core_state_machine.c:424 (sofia/internal/sip:201@110.143.31.101:1178) State INIT
2012-07-26 09:37:35.198097 [DEBUG] mod_sofia.c:85 sofia/internal/sip:201@110.143.31.101:1178 SOFIA INIT
2012-07-26 09:37:35.198097 [DEBUG] sofia_glue.c:2602 Local SDP:
v=0
o=FreeSWITCH 1343234313 1343234314 IN IP4 203.174.163.226
s=FreeSWITCH
c=IN IP4 203.174.163.226
t=0 0
m=audio 25142 RTP/AVP 8 0 3 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2012-07-26 09:37:35.198097 [DEBUG] mod_sofia.c:125 (sofia/internal/sip:201@110.143.31.101:1178) State Change CS_INIT -> CS_ROUTING
2012-07-26 09:37:35.198097 [DEBUG] switch_core_session.c:1228 Send signal sofia/internal/sip:201@110.143.31.101:1178 [BREAK]
2012-07-26 09:37:35.198097 [DEBUG] switch_core_state_machine.c:424 (sofia/internal/sip:201@110.143.31.101:1178) State INIT going to sleep
2012-07-26 09:37:35.198097 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:201@110.143.31.101:1178) Running State Change CS_ROUTING
2012-07-26 09:37:35.198097 [DEBUG] switch_channel.c:1919 (sofia/internal/sip:201@110.143.31.101:1178) Callstate Change DOWN -> RINGING
2012-07-26 09:37:35.198097 [DEBUG] switch_core_session.c:923 Send signal sofia/internal/sip:201@110.143.31.101:1178 [BREAK]
2012-07-26 09:37:35.198097 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/sip:201@110.143.31.101:1178) State ROUTING
2012-07-26 09:37:35.198097 [DEBUG] mod_sofia.c:148 sofia/internal/sip:201@110.143.31.101:1178 SOFIA ROUTING
2012-07-26 09:37:35.198097 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sip:201@110.143.31.101:1178) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2012-07-26 09:37:35.198097 [DEBUG] switch_core_session.c:1228 Send signal sofia/internal/sip:201@110.143.31.101:1178 [BREAK]
2012-07-26 09:37:35.198097 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/sip:201@110.143.31.101:1178) State ROUTING going to sleep
2012-07-26 09:37:35.198097 [DEBUG] switch_core_state_machine.c:385 (sofia/internal/sip:201@110.143.31.101:1178) Running State Change CS_CONSUME_MEDIA
2012-07-26 09:37:35.198097 [DEBUG] switch_core_state_machine.c:452 (sofia/internal/sip:201@110.143.31.101:1178) State CONSUME_MEDIA
2012-07-26 09:37:35.198097 [DEBUG] switch_core_state_machine.c:452 (sofia/internal/sip:201@110.143.31.101:1178) State CONSUME_MEDIA going to sleep
2012-07-26 09:37:35.198097 [DEBUG] sofia.c:5838 Channel sofia/internal/sip:201@110.143.31.101:1178 entering state [calling][0]
2012-07-26 09:37:35.318096 [DEBUG] switch_core_session.c:923 Send signal sofia/internal/sip:201@110.143.31.101:1178 [BREAK]
2012-07-26 09:37:35.318096 [DEBUG] switch_core_session.c:923 Send signal sofia/internal/sip:201@110.143.31.101:1178 [BREAK]
2012-07-26 09:37:35.338097 [DEBUG] sofia.c:5838 Channel sofia/internal/sip:201@110.143.31.101:1178 entering state [proceeding][180]
2012-07-26 09:37:35.338097 [NOTICE] sofia.c:5930 Ring-Ready sofia/internal/sip:201@110.143.31.101:1178!
2012-07-26 09:37:35.338097 [INFO] switch_ivr_originate.c:1156 Sending early media
2012-07-26 09:37:35.338097 [DEBUG] sofia_glue.c:3269 AUDIO RTP [sofia/internal/306@domain1.com] 203.174.163.226 port 26698 -> 115.64.93.203 port 55938 codec: 8 ms: 20
2012-07-26 09:37:35.338097 [DEBUG] switch_rtp.c:1680 Starting timer [soft] 160 bytes per 20ms
2012-07-26 09:37:35.338097 [DEBUG] sofia_glue.c:3491 Setting Jitterbuffer to 60ms (3 frames)
2012-07-26 09:37:35.338097 [DEBUG] sofia_glue.c:3533 Set 2833 dtmf send payload to 101
2012-07-26 09:37:35.338097 [DEBUG] sofia_glue.c:3539 Set 2833 dtmf receive payload to 101
2012-07-26 09:37:35.338097 [DEBUG] sofia_glue.c:3566 sofia/internal/306@domain1.com Set rtp dtmf delay to 40
2012-07-26 09:37:35.338097 [DEBUG] mod_sofia.c:2606 Ring SDP:
v=0
o=FreeSWITCH 1343232757 1343232758 IN IP4 203.174.163.226
s=FreeSWITCH
c=IN IP4 203.174.163.226
t=0 0
m=audio 26698 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
2012-07-26 09:37:35.338097 [NOTICE] mod_sofia.c:2609 Pre-Answer sofia/internal/306@domain1.com!
2012-07-26 09:37:35.338097 [DEBUG] switch_channel.c:3042 (sofia/internal/306@domain1.com) Callstate Change RINGING -> EARLY
2012-07-26 09:37:35.338097 [DEBUG] switch_core_session.c:777 Send signal sofia/internal/306@domain1.com [BREAK]