[Freeswitch-users] Getting 502 Bad Gateway with 1.0.5.pre9

Wed Dec 16 14:23:11 PST 2009

I upgraded to the latest 1.0.5pre9 and now if I try to call from an internal
phone to an external number on my Sangoma PRI, I get a "502 Bad Gateway"
reply.  Below is the console loglevel 7 output.  It says the destination is
out-of-order.  I'm not sure what this means.  Any help is appreciated.

2009-12-16 14:10:46.410656 [DEBUG] sofia.c:5285 0 acls to check for proxy
2009-12-16 14:10:46.411629 [DEBUG] sofia.c:5303 network ip is a proxy [0]
2009-12-16 14:10:46.411629 [DEBUG] sofia.c:5331 IP 192.168.72.32 Rejected by
acl "domains". Falling back to Digest auth.
2009-12-16 14:10:46.452626 [DEBUG] sofia.c:5285 0 acls to check for proxy
2009-12-16 14:10:46.452626 [DEBUG] sofia.c:5303 network ip is a proxy [0]
2009-12-16 14:10:46.452626 [DEBUG] sofia.c:5331 IP 192.168.72.32 Rejected by
acl "domains". Falling back to Digest auth.
2009-12-16 14:10:46.457607 [NOTICE] switch_channel.c:613 New Channel
sofia/internal/5381 at 192.168.72.141:5060
[e58e763f-7688-4600-aa70-481bbc359f58]
2009-12-16 14:10:46.457607 [DEBUG] sofia.c:3787 Channel
sofia/internal/5381 at 192.168.72.141:5060 entering state [received][100]
2009-12-16 14:10:46.457607 [DEBUG] sofia.c:3798 Remote SDP:
v=0
o=TC 1100638826 1100638826 IN IP4 192.168.72.32
s=session
c=IN IP4 192.168.72.32
t=0 0
m=audio 1760 RTP/AVP 0 18 4 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=rtpmap:4 G723/8000
a=rtpmap:101 telephone-event/8000/1
a=ptime:20
a=ptime:20

2009-12-16 14:10:46.457607 [DEBUG] sofia.c:3923
(sofia/internal/5381 at 192.168.72.141:5060) State Change CS_NEW -> CS_INIT
2009-12-16 14:10:46.457607 [DEBUG] switch_core_session.c:1018 Send signal
sofia/internal/5381 at 192.168.72.141:5060 [BREAK]
2009-12-16 14:10:46.457607 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/5381 at 192.168.72.141:5060) Running State Change CS_INIT
2009-12-16 14:10:46.457607 [DEBUG] switch_core_state_machine.c:338
(sofia/internal/5381 at 192.168.72.141:5060) State INIT
2009-12-16 14:10:46.457607 [DEBUG] mod_sofia.c:83
sofia/internal/5381 at 192.168.72.141:5060 SOFIA INIT
2009-12-16 14:10:46.457607 [DEBUG] mod_sofia.c:111
(sofia/internal/5381 at 192.168.72.141:5060) State Change CS_INIT -> CS_ROUTING
2009-12-16 14:10:46.457607 [DEBUG] switch_core_session.c:1018 Send signal
sofia/internal/5381 at 192.168.72.141:5060 [BREAK]
2009-12-16 14:10:46.457607 [DEBUG] switch_core_state_machine.c:338
(sofia/internal/5381 at 192.168.72.141:5060) State INIT going to sleep
2009-12-16 14:10:46.457607 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/5381 at 192.168.72.141:5060) Running State Change CS_ROUTING
2009-12-16 14:10:46.458582 [DEBUG] switch_core_state_machine.c:341
(sofia/internal/5381 at 192.168.72.141:5060) State ROUTING
2009-12-16 14:10:46.458582 [DEBUG] mod_sofia.c:132
sofia/internal/5381 at 192.168.72.141:5060 SOFIA ROUTING
2009-12-16 14:10:46.458582 [DEBUG] switch_core_state_machine.c:78
sofia/internal/5381 at 192.168.72.141:5060 Standard ROUTING
2009-12-16 14:10:46.458582 [INFO] mod_dialplan_xml.c:408 Processing
Anonymous->93491028 in context default
Dialplan: sofia/internal/5381 at 192.168.72.141:5060 parsing [default->unloop]
continue=false
Dialplan: sofia/internal/5381 at 192.168.72.141:5060 Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/5381 at 192.168.72.141:5060 Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/5381 at 192.168.72.141:5060 parsing
[default->tod_example] continue=true
Dialplan: day of week[4] =~ 2-6 (PASS)
Dialplan: hour[14] =~ 9-18 (PASS)
Dialplan: sofia/internal/5381 at 192.168.72.141:5060 Date/Time Match (PASS)
[tod_example] break=on-false
Dialplan: sofia/internal/5381 at 192.168.72.141:5060 Action set(open=true)
Dialplan: sofia/internal/5381 at 192.168.72.141:5060 parsing
[default->holiday_example] continue=true
Dialplan: month[12] =~ 1 (FAIL)
Dialplan: sofia/internal/5381 at 192.168.72.141:5060 Date/Time Match (FAIL)
[holiday_example] break=on-false
Dialplan: sofia/internal/5381 at 192.168.72.141:5060 parsing
[default->Mediant1000] continue=false
Dialplan: sofia/internal/5381 at 192.168.72.141:5060 Regex (FAIL) [Mediant1000]
destination_number(93491028) =~ /^8(\d+)$/ break=on-false
Dialplan: sofia/internal/5381 at 192.168.72.141:5060 parsing
[default->SangomaPRI] continue=false
Dialplan: sofia/internal/5381 at 192.168.72.141:5060 Regex (PASS) [SangomaPRI]
destination_number(93491028) =~ /^9(\d+)$/ break=on-false
Dialplan: sofia/internal/5381 at 192.168.72.141:5060 Action
set(effective_caller_id_number=425740${caller_id_number})
Dialplan: sofia/internal/5381 at 192.168.72.141:5060 Action
bridge(openzap/smg_prid/a/3491028 at g1)
2009-12-16 14:10:46.459538 [DEBUG] switch_core_state_machine.c:122
(sofia/internal/5381 at 192.168.72.141:5060) State Change CS_ROUTING ->
CS_EXECUTE
2009-12-16 14:10:46.459538 [DEBUG] switch_core_session.c:1018 Send signal
sofia/internal/5381 at 192.168.72.141:5060 [BREAK]
2009-12-16 14:10:46.459538 [DEBUG] switch_core_state_machine.c:341
(sofia/internal/5381 at 192.168.72.141:5060) State ROUTING going to sleep
2009-12-16 14:10:46.459538 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/5381 at 192.168.72.141:5060) Running State Change CS_EXECUTE
2009-12-16 14:10:46.459538 [DEBUG] switch_core_state_machine.c:348
(sofia/internal/5381 at 192.168.72.141:5060) State EXECUTE
2009-12-16 14:10:46.459538 [DEBUG] mod_sofia.c:181
sofia/internal/5381 at 192.168.72.141:5060 SOFIA EXECUTE
2009-12-16 14:10:46.459538 [DEBUG] switch_core_state_machine.c:159
sofia/internal/5381 at 192.168.72.141:5060 Standard EXECUTE
EXECUTE sofia/internal/5381 at 192.168.72.141:5060 set(open=true)
2009-12-16 14:10:46.459538 [DEBUG] mod_dptools.c:768
sofia/internal/5381 at 192.168.72.141:5060 SET [open]=[true]
EXECUTE sofia/internal/5381 at 192.168.72.141:5060
set(effective_caller_id_number=4257405381)
2009-12-16 14:10:46.460549 [DEBUG] mod_dptools.c:768
sofia/internal/5381 at 192.168.72.141:5060 SET
[effective_caller_id_number]=[4257405381]
EXECUTE sofia/internal/5381 at 192.168.72.141:5060
bridge(openzap/smg_prid/a/3491028 at g1)
2009-12-16 14:10:46.479629 [ERR] mod_openzap.c:945 Invalid dial string
2009-12-16 14:10:46.479629 [ERR] switch_ivr_originate.c:2249 Cannot create
outgoing channel of type [openzap] cause: [DESTINATION_OUT_OF_ORDER]
2009-12-16 14:10:46.479629 [DEBUG] switch_ivr_originate.c:3009 Originate
Resulted in Error Cause: 27 [DESTINATION_OUT_OF_ORDER]
2009-12-16 14:10:46.488521 [INFO] mod_dptools.c:2303 Originate Failed.
Cause: DESTINATION_OUT_OF_ORDER
2009-12-16 14:10:46.488521 [NOTICE] mod_dptools.c:2366 Hangup
sofia/internal/5381 at 192.168.72.141:5060 [CS_EXECUTE]
[DESTINATION_OUT_OF_ORDER]
2009-12-16 14:10:46.488521 [DEBUG] switch_channel.c:1912 Send signal
sofia/internal/5381 at 192.168.72.141:5060 [KILL]
2009-12-16 14:10:46.488521 [DEBUG] switch_core_session.c:1018 Send signal
sofia/internal/5381 at 192.168.72.141:5060 [BREAK]
2009-12-16 14:10:46.488521 [DEBUG] switch_core_state_machine.c:348
(sofia/internal/5381 at 192.168.72.141:5060) State EXECUTE going to sleep
2009-12-16 14:10:46.488521 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/5381 at 192.168.72.141:5060) Running State Change CS_HANGUP
2009-12-16 14:10:46.489603 [DEBUG] switch_core_state_machine.c:494
(sofia/internal/5381 at 192.168.72.141:5060) State HANGUP
2009-12-16 14:10:46.489603 [DEBUG] mod_sofia.c:358 Channel
sofia/internal/5381 at 192.168.72.141:5060 hanging up, cause:
DESTINATION_OUT_OF_ORDER
2009-12-16 14:10:46.489603 [DEBUG] mod_sofia.c:421 Responding to INVITE
with: 502
2009-12-16 14:10:46.489603 [DEBUG] switch_core_state_machine.c:46
sofia/internal/5381 at 192.168.72.141:5060 Standard HANGUP, cause:
DESTINATION_OUT_OF_ORDER
2009-12-16 14:10:46.489603 [DEBUG] switch_core_state_machine.c:494
(sofia/internal/5381 at 192.168.72.141:5060) State HANGUP going to sleep
2009-12-16 14:10:46.489603 [DEBUG] switch_core_state_machine.c:333
(sofia/internal/5381 at 192.168.72.141:5060) State Change CS_HANGUP ->
CS_REPORTING
2009-12-16 14:10:46.489603 [DEBUG] switch_core_session.c:1018 Send signal
sofia/internal/5381 at 192.168.72.141:5060 [BREAK]
2009-12-16 14:10:46.489603 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/5381 at 192.168.72.141:5060) Running State Change CS_REPORTING
2009-12-16 14:10:46.489603 [DEBUG] switch_core_state_machine.c:585
(sofia/internal/5381 at 192.168.72.141:5060) State REPORTING
2009-12-16 14:10:46.562662 [DEBUG] switch_core_state_machine.c:53
sofia/internal/5381 at 192.168.72.141:5060 Standard REPORTING, cause:
DESTINATION_OUT_OF_ORDER
2009-12-16 14:10:46.562662 [DEBUG] switch_core_state_machine.c:585
(sofia/internal/5381 at 192.168.72.141:5060) State REPORTING going to sleep
2009-12-16 14:10:46.562662 [DEBUG] switch_core_state_machine.c:327
(sofia/internal/5381 at 192.168.72.141:5060) State Change CS_REPORTING ->
CS_DESTROY
2009-12-16 14:10:46.562662 [DEBUG] switch_core_session.c:1018 Send signal
sofia/internal/5381 at 192.168.72.141:5060 [BREAK]
2009-12-16 14:10:46.562662 [DEBUG] switch_core_session.c:1155 Session 1
(sofia/internal/5381 at 192.168.72.141:5060) Locked, Waiting on external
entities
2009-12-16 14:10:46.562662 [NOTICE] switch_core_session.c:1173 Session 1
(sofia/internal/5381 at 192.168.72.141:5060) Ended
2009-12-16 14:10:46.562662 [NOTICE] switch_core_session.c:1175 Close Channel
sofia/internal/5381 at 192.168.72.141:5060 [CS_DESTROY]
2009-12-16 14:10:46.562662 [DEBUG] switch_core_state_machine.c:423
(sofia/internal/5381 at 192.168.72.141:5060) Running State Change CS_DESTROY
2009-12-16 14:10:46.562662 [DEBUG] switch_core_state_machine.c:434
(sofia/internal/5381 at 192.168.72.141:5060) State DESTROY
2009-12-16 14:10:46.562662 [DEBUG] mod_sofia.c:293
sofia/internal/5381 at 192.168.72.141:5060 SOFIA DESTROY
2009-12-16 14:10:46.562662 [DEBUG] switch_core_state_machine.c:60
sofia/internal/5381 at 192.168.72.141:5060 Standard DESTROY
2009-12-16 14:10:46.562662 [DEBUG] switch_core_state_machine.c:434
(sofia/internal/5381 at 192.168.72.141:5060) State DESTROY going to sleep

Best Regards,
Jerry