[Freeswitch-users] WARNING On Inbound Call Question

Tue Nov 3 13:35:05 PST 2009

I have my Freeswitch server with an installed Sangoma A101D card.  Most
everything works okay, however, when I get an inbound call from the PSTN, I
see the following warning show up in the log.  Additionally, the caller (on
the PSTN) does not hear ringback, and if the call is not answered within
about 12 seconds, the call ends (so it doesn't go to voice mail).  If I make
a call from one internal phone to another, then it will go to voice mail
after 30 seconds.

Here are the two warnings:

[WARNING] ss7_boost_client.c:218 TX EVENT (N): CALL_START_ACK:(81) [w1g1]
Rc=0 CSid=0 Seq=11 
[WARNING] mod_openzap.c:761 VETO Changing state on 1:1 from PROGRESS to
PROGRESS_MEDIA

Here is the log of the warning upon an inbound call:

freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 2009-11-02 09:06:01.664835
[WARNING] ozmod_ss7_boost.c:1141 RX EVENT: CALL_START:(80) [w1g1] CSid=0
Seq=12 Cn=[N/A] Cd=[5384] Ci=[4253813176]
2009-11-02 09:06:01.665824 [DEBUG] ozmod_ss7_boost.c:655 Changing state on
1:1 from DOWN to RING
2009-11-02 09:06:01.665824 [DEBUG] ozmod_ss7_boost.c:841 1:1 STATE [RING]
2009-11-02 09:06:01.665824 [DEBUG] mod_openzap.c:1481 got clear channel sig
[START]
2009-11-02 09:06:01.665824 [DEBUG] mod_openzap.c:344 Set codec PCMU 20ms
2009-11-02 09:06:01.665824 [DEBUG] mod_openzap.c:1184 Connect inbound
channel OpenZAP/1:1/5384
2009-11-02 09:06:01.665824 [NOTICE] switch_channel.c:602 New Channel
OpenZAP/1:1/5384 [b678f311-ab74-4cc1-afac-b83d89a53132]
2009-11-02 09:06:01.665824 [DEBUG] mod_openzap.c:1192 (OpenZAP/1:1/5384)
State Change CS_NEW -> CS_INIT
2009-11-02 09:06:01.665824 [DEBUG] switch_core_session.c:932 Send signal
OpenZAP/1:1/5384 [BREAK]
2009-11-02 09:06:01.665824 [DEBUG] switch_core_state_machine.c:398
(OpenZAP/1:1/5384) Running State Change CS_INIT
2009-11-02 09:06:01.665824 [DEBUG] switch_core_state_machine.c:481
(OpenZAP/1:1/5384) State INIT
2009-11-02 09:06:01.665824 [DEBUG] mod_openzap.c:368 (OpenZAP/1:1/5384)
State Change CS_INIT -> CS_ROUTING
2009-11-02 09:06:01.665824 [DEBUG] switch_core_session.c:932 Send signal
OpenZAP/1:1/5384 [BREAK]
2009-11-02 09:06:01.665824 [DEBUG] switch_core_state_machine.c:481
(OpenZAP/1:1/5384) State INIT going to sleep
2009-11-02 09:06:01.665824 [DEBUG] switch_core_state_machine.c:398
(OpenZAP/1:1/5384) Running State Change CS_ROUTING
2009-11-02 09:06:01.665824 [DEBUG] switch_core_state_machine.c:484
(OpenZAP/1:1/5384) State ROUTING
2009-11-02 09:06:01.665824 [DEBUG] mod_openzap.c:391 OpenZAP/1:1/5384
CHANNEL ROUTING
2009-11-02 09:06:01.665824 [DEBUG] switch_core_state_machine.c:78
OpenZAP/1:1/5384 Standard ROUTING
2009-11-02 09:06:01.665824 [INFO] mod_dialplan_xml.c:315 Processing
4253813176->5384 in context default
Dialplan: OpenZAP/1:1/5384 parsing [default->unloop] continue=false
Dialplan: OpenZAP/1:1/5384 Regex (PASS) [unloop] ${unroll_loops}(true) =~
/^true$/ break=on-false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [unloop] ${sip_looped_call}() =~
/^true$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->tod_example] continue=true
Dialplan: OpenZAP/1:1/5384 Absolute Condition [tod_example]
Dialplan: OpenZAP/1:1/5384 Action set(open=true)
Dialplan: OpenZAP/1:1/5384 parsing [default->SangomaPRI] continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [SangomaPRI]
destination_number(5384) =~ /^9(\d+)$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->global-intercept]
continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [global-intercept]
destination_number(5384) =~ /^(5380)$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->group-intercept] continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [group-intercept]
destination_number(5384) =~ /^\*8$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->intercept-ext] continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [intercept-ext]
destination_number(5384) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->redial] continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [redial] destination_number(5384) =~
/^870$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->global] continue=true
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [global] ${call_debug}(false) =~
/^true$/ break=never
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [global] ${sip_has_crypto}() =~
/^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: OpenZAP/1:1/5384 Absolute Condition [global]
Dialplan: OpenZAP/1:1/5384 Action
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: OpenZAP/1:1/5384 Action
hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_numbe
r})
Dialplan: OpenZAP/1:1/5384 Action
hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: OpenZAP/1:1/5384 parsing [default->snom-demo-2] continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [snom-demo-2]
destination_number(5384) =~ /^9001$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->snom-demo-1] continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [snom-demo-1]
destination_number(5384) =~ /^9000$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->eavesdrop] continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [eavesdrop] destination_number(5384)
=~ /^88(.*)$|^\*0(.*)$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->eavesdrop] continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [eavesdrop] destination_number(5384)
=~ /^779$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->call_return] continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [call_return]
destination_number(5384) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->del-group] continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [del-group] destination_number(5384)
=~ /^80(\d{2})$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->add-group] continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [add-group] destination_number(5384)
=~ /^81(\d{2})$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->call-group-simo] continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [call-group-simo]
destination_number(5384) =~ /^82(\d{2})$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->call-group-order]
continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [call-group-order]
destination_number(5384) =~ /^83(\d{2})$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->extension-intercom]
continue=false
Dialplan: OpenZAP/1:1/5384 Regex (FAIL) [extension-intercom]
destination_number(5384) =~ /^8(5[34][8901][0-9])$/ break=on-false
Dialplan: OpenZAP/1:1/5384 parsing [default->Local_Extension] continue=false
Dialplan: OpenZAP/1:1/5384 Regex (PASS) [Local_Extension]
destination_number(5384) =~ /^(5[34][8901][0-9])$/ break=on-false
Dialplan: OpenZAP/1:1/5384 Action set(dialed_extension=5384)
Dialplan: OpenZAP/1:1/5384 Action export(dialed_extension=5384)
Dialplan: OpenZAP/1:1/5384 Action bind_meta_app(1 b s execute_extension::dx
XML features)
Dialplan: OpenZAP/1:1/5384 Action bind_meta_app(2 b s
record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strft
ime(%Y-%m-%d-%H-%M-%S)}.wav)
Dialplan: OpenZAP/1:1/5384 Action bind_meta_app(3 b s execute_extension::cf
XML features)
Dialplan: OpenZAP/1:1/5384 Action set(ringback=${us-ring})
Dialplan: OpenZAP/1:1/5384 Action set(transfer_ringback=local_stream://moh)
Dialplan: OpenZAP/1:1/5384 Action set(call_timeout=30)
Dialplan: OpenZAP/1:1/5384 Action set(hangup_after_bridge=true)
Dialplan: OpenZAP/1:1/5384 Action set(continue_on_fail=true)
Dialplan: OpenZAP/1:1/5384 Action
hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_numbe
r})
Dialplan: OpenZAP/1:1/5384 Action
hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: OpenZAP/1:1/5384 Action
set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name}
var callgroup)})
Dialplan: OpenZAP/1:1/5384 Action
hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: OpenZAP/1:1/5384 Action
bridge(user/${dialed_extension}@${domain_name})
Dialplan: OpenZAP/1:1/5384 Action answer()
Dialplan: OpenZAP/1:1/5384 Action sleep(1000)
Dialplan: OpenZAP/1:1/5384 Action voicemail(default ${domain_name}
${dialed_extension})
2009-11-02 09:06:01.666685 [DEBUG] switch_core_state_machine.c:114
(OpenZAP/1:1/5384) State Change CS_ROUTING -> CS_EXECUTE
2009-11-02 09:06:01.666685 [DEBUG] switch_core_session.c:932 Send signal
OpenZAP/1:1/5384 [BREAK]
2009-11-02 09:06:01.666685 [DEBUG] switch_core_state_machine.c:484
(OpenZAP/1:1/5384) State ROUTING going to sleep
2009-11-02 09:06:01.666685 [DEBUG] switch_core_state_machine.c:398
(OpenZAP/1:1/5384) Running State Change CS_EXECUTE
2009-11-02 09:06:01.666685 [DEBUG] switch_core_state_machine.c:491
(OpenZAP/1:1/5384) State EXECUTE
2009-11-02 09:06:01.666685 [DEBUG] mod_openzap.c:408 OpenZAP/1:1/5384
CHANNEL EXECUTE
2009-11-02 09:06:01.666685 [DEBUG] switch_core_state_machine.c:151
OpenZAP/1:1/5384 Standard EXECUTE
EXECUTE OpenZAP/1:1/5384 set(open=true)
2009-11-02 09:06:01.666685 [DEBUG] mod_dptools.c:748 OpenZAP/1:1/5384 SET
[open]=[true]
EXECUTE OpenZAP/1:1/5384
hash(insert/192.168.72.141-spymap/4253813176/b678f311-ab74-4cc1-afac-b83d89a
53132)
EXECUTE OpenZAP/1:1/5384
hash(insert/192.168.72.141-last_dial/4253813176/5384)
EXECUTE OpenZAP/1:1/5384
hash(insert/192.168.72.141-last_dial/global/b678f311-ab74-4cc1-afac-b83d89a5
3132)
EXECUTE OpenZAP/1:1/5384 set(dialed_extension=5384)
2009-11-02 09:06:01.667682 [DEBUG] mod_dptools.c:748 OpenZAP/1:1/5384 SET
[dialed_extension]=[5384]
EXECUTE OpenZAP/1:1/5384 export(dialed_extension=5384)
2009-11-02 09:06:01.667682 [DEBUG] mod_dptools.c:886 EXPORT
[dialed_extension]=[5384]
EXECUTE OpenZAP/1:1/5384 bind_meta_app(1 b s execute_extension::dx XML
features)
2009-11-02 09:06:01.667682 [INFO] switch_ivr_async.c:1795 Bound B-Leg: 1
execute_extension::dx XML features
EXECUTE OpenZAP/1:1/5384 bind_meta_app(2 b s
record_session::/usr/local/freeswitch/recordings/4253813176.2009-11-02-09-06
-01.wav)
2009-11-02 09:06:01.668708 [INFO] switch_ivr_async.c:1795 Bound B-Leg: 2
record_session::/usr/local/freeswitch/recordings/4253813176.2009-11-02-09-06
-01.wav
EXECUTE OpenZAP/1:1/5384 bind_meta_app(3 b s execute_extension::cf XML
features)
2009-11-02 09:06:01.668708 [INFO] switch_ivr_async.c:1795 Bound B-Leg: 3
execute_extension::cf XML features
EXECUTE OpenZAP/1:1/5384 set(ringback=%(2000,4000,440.0,480.0))
2009-11-02 09:06:01.668708 [DEBUG] mod_dptools.c:748 OpenZAP/1:1/5384 SET
[ringback]=[%(2000,4000,440.0,480.0)]
EXECUTE OpenZAP/1:1/5384 set(transfer_ringback=local_stream://moh)
2009-11-02 09:06:01.668708 [DEBUG] mod_dptools.c:748 OpenZAP/1:1/5384 SET
[transfer_ringback]=[local_stream://moh]
EXECUTE OpenZAP/1:1/5384 set(call_timeout=30)
2009-11-02 09:06:01.668708 [DEBUG] mod_dptools.c:748 OpenZAP/1:1/5384 SET
[call_timeout]=[30]
EXECUTE OpenZAP/1:1/5384 set(hangup_after_bridge=true)
2009-11-02 09:06:01.669681 [DEBUG] mod_dptools.c:748 OpenZAP/1:1/5384 SET
[hangup_after_bridge]=[true]
EXECUTE OpenZAP/1:1/5384 set(continue_on_fail=true)
2009-11-02 09:06:01.669681 [DEBUG] mod_dptools.c:748 OpenZAP/1:1/5384 SET
[continue_on_fail]=[true]
EXECUTE OpenZAP/1:1/5384
hash(insert/192.168.72.141-call_return/5384/4253813176)
EXECUTE OpenZAP/1:1/5384
hash(insert/192.168.72.141-last_dial_ext/5384/b678f311-ab74-4cc1-afac-b83d89
a53132)
EXECUTE OpenZAP/1:1/5384 set(called_party_callgroup=techsupport)
2009-11-02 09:06:01.670679 [DEBUG] mod_dptools.c:748 OpenZAP/1:1/5384 SET
[called_party_callgroup]=[techsupport]
EXECUTE OpenZAP/1:1/5384
hash(insert/192.168.72.141-last_dial/techsupport/b678f311-ab74-4cc1-afac-b83
d89a53132)
EXECUTE OpenZAP/1:1/5384 bridge(user/5384 at 192.168.72.141)
2009-11-02 09:06:01.671683 [DEBUG] switch_ivr_originate.c:1027 variable
string 0 = [presence_id=5384 at 192.168.72.141]
2009-11-02 09:06:01.671683 [NOTICE] switch_channel.c:602 New Channel
sofia/internal/sip:5384 at 192.168.72.163:5060
[9e7b8fae-6194-430c-951b-948ebd2c2a3b]
2009-11-02 09:06:01.671683 [DEBUG] mod_sofia.c:2811
(sofia/internal/sip:5384 at 192.168.72.163:5060) State Change CS_NEW -> CS_INIT
2009-11-02 09:06:01.672688 [DEBUG] switch_core_session.c:932 Send signal
sofia/internal/sip:5384 at 192.168.72.163:5060 [BREAK]
2009-11-02 09:06:01.672688 [DEBUG] switch_core_state_machine.c:398
(sofia/internal/sip:5384 at 192.168.72.163:5060) Running State Change CS_INIT
2009-11-02 09:06:01.672688 [DEBUG] switch_core_state_machine.c:481
(sofia/internal/sip:5384 at 192.168.72.163:5060) State INIT
2009-11-02 09:06:01.672688 [DEBUG] mod_sofia.c:83
sofia/internal/sip:5384 at 192.168.72.163:5060 SOFIA INIT
2009-11-02 09:06:01.672688 [DEBUG] mod_sofia.c:111
(sofia/internal/sip:5384 at 192.168.72.163:5060) State Change CS_INIT ->
CS_ROUTING
2009-11-02 09:06:01.672688 [DEBUG] switch_core_session.c:932 Send signal
sofia/internal/sip:5384 at 192.168.72.163:5060 [BREAK]
2009-11-02 09:06:01.672688 [DEBUG] switch_core_state_machine.c:481
(sofia/internal/sip:5384 at 192.168.72.163:5060) State INIT going to sleep
2009-11-02 09:06:01.672688 [DEBUG] switch_core_state_machine.c:398
(sofia/internal/sip:5384 at 192.168.72.163:5060) Running State Change
CS_ROUTING
2009-11-02 09:06:01.672688 [DEBUG] switch_core_state_machine.c:484
(sofia/internal/sip:5384 at 192.168.72.163:5060) State ROUTING
2009-11-02 09:06:01.672688 [DEBUG] mod_sofia.c:130
sofia/internal/sip:5384 at 192.168.72.163:5060 SOFIA ROUTING
2009-11-02 09:06:01.672688 [DEBUG] switch_ivr_originate.c:63
(sofia/internal/sip:5384 at 192.168.72.163:5060) State Change CS_ROUTING ->
CS_CONSUME_MEDIA
2009-11-02 09:06:01.672688 [DEBUG] switch_core_session.c:932 Send signal
sofia/internal/sip:5384 at 192.168.72.163:5060 [BREAK]
2009-11-02 09:06:01.672688 [DEBUG] switch_core_state_machine.c:484
(sofia/internal/sip:5384 at 192.168.72.163:5060) State ROUTING going to sleep
2009-11-02 09:06:01.672688 [DEBUG] switch_core_state_machine.c:398
(sofia/internal/sip:5384 at 192.168.72.163:5060) Running State Change
CS_CONSUME_MEDIA
2009-11-02 09:06:01.672688 [DEBUG] sofia.c:3289 Channel
sofia/internal/sip:5384 at 192.168.72.163:5060 entering state [calling][0]
2009-11-02 09:06:01.672688 [DEBUG] switch_core_state_machine.c:503
(sofia/internal/sip:5384 at 192.168.72.163:5060) State CONSUME_MEDIA
2009-11-02 09:06:01.672688 [DEBUG] switch_ivr_originate.c:1701
OpenZAP/1:1/5384 receive message [PROGRESS]
2009-11-02 09:06:01.673742 [DEBUG] mod_openzap.c:759 Changing state on 1:1
from RING to PROGRESS
2009-11-02 09:06:01.674787 [DEBUG] ozmod_ss7_boost.c:841 1:1 STATE
[PROGRESS]
2009-11-02 09:06:01.675844 [WARNING] ss7_boost_client.c:218 TX EVENT (N):
CALL_START_ACK:(81) [w1g1] Rc=0 CSid=0 Seq=11 
2009-11-02 09:06:01.684776 [WARNING] mod_openzap.c:761 VETO Changing state
on 1:1 from PROGRESS to PROGRESS_MEDIA
2009-11-02 09:06:01.684776 [DEBUG] switch_core_session.c:630 Send signal
OpenZAP/1:1/5384 [BREAK]
2009-11-02 09:06:01.684776 [NOTICE] switch_ivr_originate.c:1701 Pre-Answer
OpenZAP/1:1/5384!
2009-11-02 09:06:01.684776 [DEBUG] switch_ivr_originate.c:1718 Raw Codec
Activation Success L16 at 8000hz 1 channel 20ms
2009-11-02 09:06:01.684776 [DEBUG] switch_ivr_originate.c:1777 Play Ringback
Tone [%(2000,4000,440.0,480.0)]
2009-11-02 09:06:01.693835 [DEBUG] sofia.c:3289 Channel
sofia/internal/sip:5384 at 192.168.72.163:5060 entering state [proceeding][180]
2009-11-02 09:06:01.693835 [NOTICE] sofia.c:3353 Ring-Ready
sofia/internal/sip:5384 at 192.168.72.163:5060!
2009-11-02 09:06:01.705777 [DEBUG] switch_core_io.c:649 OpenZAP/1:1/5384
receive message [TRANSCODING_NECESSARY]

freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 
freeswitch at TeoProxy.greyhawk.tonecommander.com> 

Best Regards,
Jerry