Default MoH not playing via local_stream when I put a call on hold.

1,360 views

Skip to first unread message

J. Erickson

unread,

Jan 15, 2015, 7:46:19 PM1/15/15

to 2600h...@googlegroups.com

This is a really strange issue.

It could be FreeSwitch specific. If it's definitely FreeSwitch specific just let me know and I'll post in the appropriate mailing list.

Been working on it for a while, and google has not been much help. The music files are present in the appropriate location, with the appropriate permissions, and the local_stream.conf.xml is correct.

Settings are correct in kazoo-UI (all accounts are set to Default MoH), everything looks fine in bigcouch.

Debug logs don't show any errors or warnings when I put someone on hold.

But nothing plays. Just silence.

This is a very default, non-tweaked install of Kazoo 3.18 and all the related RPMs out of the staging repo, in a 7 physical server cluster.

This is the output of the show_local_stream commands on fs_cli (shows the same on both of my freeswitch servers, music doesn't play for calls handled by either server):

show_local_stream

default,/usr/share/freeswitch/sounds/music/8000

+OK

freeswitch@internal> show_local_stream default

default

location: /usr/share/freeswitch/sounds/music/8000

channels: 1

rate: 8000

interval: 20

samples: 160

prebuf: 65536

timer: soft

total: 0

shuffle: true

ready: true

stopped: false

reloading: false

+OK

freeswitch@internal>

If I issue stop_local_stream default, and then start_local_stream default, I get the following debug output immediately. Is it normal?

freeswitch@internal> stop_local_stream default

+OK

freeswitch@internal> start_local_stream default

+OK stream: default

2015-01-16 00:26:10.204354 [DEBUG] kazoo_fetch_agent.c:216 Sending configuration XML request (4519ec2a-9d16-11e4-82a2-3599fa757155) to ecal...@app01.testdomain.net <3.1221.0>

2015-01-16 00:26:10.384349 [DEBUG] kazoo_node.c:1100 Sent erlang message to ecal...@app01.testdomain.net <3.1221.0>

2015-01-16 00:26:10.384349 [DEBUG] kazoo_fetch_agent.c:277 Received configuration XML (4519ec2a-9d16-11e4-82a2-3599fa757155) after 179ms: <document type="freeswitch/xml"><section name="result" description="Route Not Found"><result status="not found"/></section></document>

freeswitch@internal>

Any insight, however little would be much appreciated. I will paste the complete freeswitch log of a call below.

Thanks.

+OK log level [7]

freeswitch@internal> 2015-01-16 00:33:48.784379 [NOTICE] switch_channel.c:1055 New Channel sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP]

2015-01-16 00:33:48.784379 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:48.784379 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Running State Change CS_NEW

2015-01-16 00:33:48.784379 [DEBUG] sofia.c:8955 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 receiving invite from WHAPPS_SERVER_PUBLIC_IP:7000 version: 1.4.14 64bit

2015-01-16 00:33:48.784379 [DEBUG] sofia.c:9077 1 acls to check for proxy

2015-01-16 00:33:48.784379 [DEBUG] sofia.c:9082 checking WHAPPS_SERVER_PUBLIC_IP against acl authoritative

2015-01-16 00:33:48.784379 [INFO] sofia.c:9084 WHAPPS_SERVER_PUBLIC_IP is a proxy according to the authoritative acl

2015-01-16 00:33:48.784379 [DEBUG] sofia.c:9094 network ip is a proxy

2015-01-16 00:33:48.784379 [DEBUG] sofia.c:9098 found auth ip [X-AUTH-IP] header of [EDGE_SBC_PUBLIC_IP]

2015-01-16 00:33:48.784379 [DEBUG] sofia.c:9130 IP EDGE_SBC_PUBLIC_IP Approved by acl "trusted[]". Access Granted.

2015-01-16 00:33:48.784379 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 entering state [received][100]

2015-01-16 00:33:48.784379 [DEBUG] sofia.c:6624 Remote SDP:

v=0

o=Sonus_UAC 25529 22048 IN IP4 TERMINATION_PROVIDERS_SIGNALING_IP

s=SIP Media Capabilities

c=IN IP4 TERMINATION_PROVIDERS_MEDIA_IP

t=0 0

m=audio 5764 RTP/AVP 0 18 101

a=rtpmap:0 PCMU/8000

a=rtpmap:18 G729/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

a=maxptime:20

2015-01-16 00:33:48.784379 [DEBUG] sofia.c:6891 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State Change CS_NEW -> CS_INIT

2015-01-16 00:33:48.784379 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:48.784379 [DEBUG] switch_core_state_machine.c:491 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State NEW

2015-01-16 00:33:48.784379 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Running State Change CS_INIT

2015-01-16 00:33:48.784379 [DEBUG] switch_core_state_machine.c:512 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State INIT

2015-01-16 00:33:48.784379 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 SOFIA INIT

2015-01-16 00:33:48.784379 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Standard INIT

2015-01-16 00:33:48.784379 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State Change CS_INIT -> CS_ROUTING

2015-01-16 00:33:48.784379 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:48.784379 [DEBUG] switch_core_state_machine.c:512 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State INIT going to sleep

2015-01-16 00:33:48.784379 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Running State Change CS_ROUTING

2015-01-16 00:33:48.784379 [DEBUG] switch_channel.c:2184 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Callstate Change DOWN -> RINGING

2015-01-16 00:33:48.784379 [DEBUG] switch_core_state_machine.c:528 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State ROUTING

2015-01-16 00:33:48.784379 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 SOFIA ROUTING

2015-01-16 00:33:48.784379 [DEBUG] switch_core_state_machine.c:166 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Standard ROUTING

2015-01-16 00:33:48.784379 [INFO] mod_dialplan_xml.c:635 Processing JD ERICKSON <MY_CELL_NUMBER>->14358797447 in context context_2

2015-01-16 00:33:48.784379 [DEBUG] kazoo_fetch_agent.c:216 Sending dialplan XML request (5670dbc2-9d17-11e4-82c3-3599fa757155) to ecal...@APP01.MY_DOMAIN.NET <1.1141.0>

2015-01-16 00:33:48.904397 [DEBUG] kazoo_node.c:1100 Sent erlang message to ecal...@APP01.MY_DOMAIN.NET <1.1141.0>

2015-01-16 00:33:48.924397 [DEBUG] kazoo_fetch_agent.c:277 Received dialplan XML (5670dbc2-9d17-11e4-82c3-3599fa757155) after 140ms: <document type="freeswitch/xml"><section name="dialplan" description="Route Park Response"><context name="context_2"><extension name="park"><condition><action application="log" data="NOTICE log|${uuid}|ecal...@APP01.MY_DOMAIN.NET won call control"/><action application="export" data="ecallmgr_Ecallmgr-Node=ecal...@APP01.MY_DOMAIN.NET"/><condition field="variable_ecallmgr_Bridge-ID" expression="^$"><action application="export" data="ecallmgr_Bridge-ID=${UUID}"/></condition><action application="set" data="ringback=%(2000,4000,440,480)"/><action application="set" data="transfer_ringback=%(2000,4000,440,480)"/><action application="ring_ready"/><action application="park"/></condition></extension></context></section></document>

Dialplan: sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 parsing [context_2->park] continue=false

|--- Dialplan: Processing recursive conditions level:1 [park_recur_1] require-nested=TRUE

|--- Dialplan: sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Regex (PASS) [park_recur_1] variable_ecallmgr_Bridge-ID() =~ /^$/ break=on-false

|--- Dialplan: sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Action export(ecallmgr_Bridge-ID=${UUID})

Dialplan: sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Absolute Condition [park]

Dialplan: sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Action log(NOTICE log|${uuid}|ecal...@APP01.MY_DOMAIN.NET won call control)

Dialplan: sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Action export(ecallmgr_Ecallmgr-Node=ecal...@APP01.MY_DOMAIN.NET)

Dialplan: sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Action set(ringback=%(2000,4000,440,480))

Dialplan: sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Action set(transfer_ringback=%(2000,4000,440,480))

Dialplan: sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Action ring_ready()

Dialplan: sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Action park()

2015-01-16 00:33:48.924397 [DEBUG] switch_core_state_machine.c:216 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State Change CS_ROUTING -> CS_EXECUTE

2015-01-16 00:33:48.924397 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:48.924397 [DEBUG] switch_core_state_machine.c:528 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State ROUTING going to sleep

2015-01-16 00:33:48.924397 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Running State Change CS_EXECUTE

2015-01-16 00:33:48.924397 [DEBUG] switch_core_state_machine.c:535 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State EXECUTE

2015-01-16 00:33:48.924397 [DEBUG] mod_sofia.c:178 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 SOFIA EXECUTE

2015-01-16 00:33:48.924397 [DEBUG] switch_core_state_machine.c:258 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Standard EXECUTE

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 export(ecallmgr_Bridge-ID=386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP)

2015-01-16 00:33:48.924397 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [ecallmgr_Bridge-ID]=[386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP]

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 log(NOTICE log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|ecal...@APP01.MY_DOMAIN.NET won call control)

2015-01-16 00:33:48.924397 [NOTICE] mod_dptools.c:1650 log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|ecal...@APP01.MY_DOMAIN.NET won call control

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 export(ecallmgr_Ecallmgr-Node=ecal...@APP01.MY_DOMAIN.NET)

2015-01-16 00:33:48.924397 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [ecallmgr_Ecallmgr-Node]=[ecal...@APP01.MY_DOMAIN.NET]

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 set(ringback=%(2000,4000,440,480))

2015-01-16 00:33:48.924397 [DEBUG] mod_dptools.c:1435 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 SET [ringback]=[%(2000,4000,440,480)]

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 set(transfer_ringback=%(2000,4000,440,480))

2015-01-16 00:33:48.924397 [DEBUG] mod_dptools.c:1435 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 SET [transfer_ringback]=[%(2000,4000,440,480)]

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 ring_ready()

2015-01-16 00:33:48.924397 [NOTICE] mod_sofia.c:2088 Ring-Ready sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060!

2015-01-16 00:33:48.924397 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:48.924397 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 entering state [early][180]

2015-01-16 00:33:48.924397 [DEBUG] switch_core_session.c:908 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:48.924397 [NOTICE] mod_dptools.c:974 Ring Ready sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060!

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 park()

2015-01-16 00:33:49.124383 [DEBUG] kazoo_node.c:1100 Sent erlang message to ecal...@APP01.MY_DOMAIN.NET <1.10484.12>

2015-01-16 00:33:49.124383 [INFO] kazoo_node.c:625 exec: uuid_setvar_multi(386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP effective_caller_id_number=MY_CELL_NUMBER;ecallmgr_Fetch-ID=5670dbc2-9d17-11e4-82c3-3599fa757155;ecallmgr_Account-ID=ad9d5ba969687ae92dd65a8b86f72d8a;ignore_display_updates=true;ecallmgr_Inception=14358797447@EDGE_SBC_PUBLIC_IP;ecallmgr_Resource-ID=52efd82ef41ff7603ae41c7a3e220ea1;effective_caller_id_name=JD ERICKSON)

2015-01-16 00:33:49.324381 [DEBUG] kazoo_node.c:1100 Sent erlang message to ecal...@APP01.MY_DOMAIN.NET <1.10527.12>

2015-01-16 00:33:49.344397 [NOTICE] kazoo_node.c:285 log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|executing ring_ready

2015-01-16 00:33:49.344397 [DEBUG] switch_core_session.c:1188 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:49.344397 [DEBUG] switch_ivr.c:614 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Command Execute ring_ready()

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 ring_ready()

2015-01-16 00:33:49.344397 [DEBUG] switch_core_session.c:908 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:49.344397 [NOTICE] mod_dptools.c:974 Ring Ready sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060!

2015-01-16 00:33:49.544379 [DEBUG] kazoo_node.c:1100 Sent erlang message to ecal...@APP01.MY_DOMAIN.NET <1.10527.12>

2015-01-16 00:33:49.544379 [DEBUG] kazoo_node.c:1122 increased received message buffer size to 2152

2015-01-16 00:33:49.544379 [NOTICE] kazoo_node.c:302 log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|building xferext extension: set continue_on_fail=true

2015-01-16 00:33:49.544379 [NOTICE] kazoo_node.c:302 log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|building xferext extension: export sip_redirect_context=context_2

2015-01-16 00:33:49.544379 [NOTICE] kazoo_node.c:302 log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|building xferext extension: set hangup_after_bridge=true

2015-01-16 00:33:49.544379 [NOTICE] kazoo_node.c:302 log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|building xferext extension: export ecallmgr_Inception=${ecallmgr_Inception}

2015-01-16 00:33:49.544379 [NOTICE] kazoo_node.c:302 log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|building xferext extension: bridge {call_timeout=20,originate_timeout=20,local_var_clobber='true'}[ecallmgr_Authorizing-ID='31ce66a0d9f6b9bc73bb0cbeb7e6bc14',ecallmgr_Owner-ID='9a00bda774d5ad8f04eaa0c63b4f43fd',ecallmgr_Account-ID='ad9d5ba969687ae92dd65a8b86f72d8a',sdp_secure_savp_only='false',sip_invite_domain='EDGE_SBC_PUBLIC_IP',presence_id='user_n7sn94mefq@AUTH_REALM.MY_AUTH_REALM_DOMAIN.NET',absolute_codec_string='^^:G722:PCMU:PCMA',leg_timeout='20',effective_callee_id_number='MY_CALLER_ID_NUMBER',effective_callee_id_name='MY_CALLER_ID_NAME',origination_callee_id_number='MY_CALLER_ID_NUMBER',origination_callee_id_name='MY_CALLER_ID_NAME',ecallmgr_Realm='AUTH_REALM.MY_AUTH_REALM_DOMAIN.NET',ecallmgr_Username='user_n7sn94mefq']sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031;transport=udp;fs_path=sip:WHAPPS_SERVER_PUBLIC_IP:7000;lr;received='sip:MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031;transport=udp',[ecallmgr_Authorizing-ID='c9cf945b7cd3810717bfef04f41d6033',ecallmgr_Owner-ID='9a00bda774d5ad8f04eaa0c63b4f43fd',ecallmgr_Account-ID='ad9d5ba969687ae92dd65a8b86f72d8a',sdp_secure_savp_only='false',sip_invite_domain='EDGE_SBC_PUBLIC_IP',presence_id='user_w7ugp8@AUTH_REALM.MY_AUTH_REALM_DOMAIN.NET',absolute_codec_string='^^:G722:PCMU:PCMA',leg_timeout='20',effective_callee_id_number='MY_CALLER_ID_NUMBER',effective_callee_id_name='MY_CALLER_ID_NAME',origination_callee_id_number='MY_CALLER_ID_NUMBER',origination_callee_id_name='MY_CALLER_ID_NAME',ecallmgr_Realm='AUTH_REALM.MY_AUTH_REALM_DOMAIN.NET',ecallmgr_Username='user_w7ugp8']sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144;transport=udp;fs_path=sip:WHAPPS_SERVER_PUBLIC_IP:7000;lr;received='sip:POLYCOM_PUBLIC_IP:1144;transport=udp'

2015-01-16 00:33:49.544379 [NOTICE] kazoo_node.c:302 log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|building xferext extension: event Event-Name=CUSTOM,Event-Subclass=whistle::masquerade,whistle_event_name=CHANNEL_EXECUTE_COMPLETE,whistle_application_name=bridge

2015-01-16 00:33:49.544379 [NOTICE] kazoo_node.c:302 log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|building xferext extension: park

2015-01-16 00:33:49.544379 [NOTICE] kazoo_node.c:305 log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|transfered call to xferext extension

2015-01-16 00:33:49.544379 [DEBUG] switch_core_session.c:1188 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:49.544379 [DEBUG] switch_channel.c:3103 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State Change CS_EXECUTE -> CS_ROUTING

2015-01-16 00:33:49.544379 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:535 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State EXECUTE going to sleep

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Running State Change CS_ROUTING

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:528 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State ROUTING

2015-01-16 00:33:49.544379 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 SOFIA ROUTING

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:166 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Standard ROUTING

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:186 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State Change CS_ROUTING -> CS_EXECUTE

2015-01-16 00:33:49.544379 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:528 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State ROUTING going to sleep

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Running State Change CS_EXECUTE

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:535 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State EXECUTE

2015-01-16 00:33:49.544379 [DEBUG] mod_sofia.c:178 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 SOFIA EXECUTE

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:258 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Standard EXECUTE

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 set(continue_on_fail=true)

2015-01-16 00:33:49.544379 [DEBUG] mod_dptools.c:1435 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 SET [continue_on_fail]=[true]

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 export(sip_redirect_context=context_2)

2015-01-16 00:33:49.544379 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [sip_redirect_context]=[context_2]

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 set(hangup_after_bridge=true)

2015-01-16 00:33:49.544379 [DEBUG] mod_dptools.c:1435 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 SET [hangup_after_bridge]=[true]

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 export(ecallmgr_Inception=14358797447@EDGE_SBC_PUBLIC_IP)

2015-01-16 00:33:49.544379 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [ecallmgr_Inception]=[14358797447@EDGE_SBC_PUBLIC_IP]

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 bridge({call_timeout=20,originate_timeout=20,local_var_clobber='true'}[ecallmgr_Authorizing-ID='31ce66a0d9f6b9bc73bb0cbeb7e6bc14',ecallmgr_Owner-ID='9a00bda774d5ad8f04eaa0c63b4f43fd',ecallmgr_Account-ID='ad9d5ba969687ae92dd65a8b86f72d8a',sdp_secure_savp_only='false',sip_invite_domain='EDGE_SBC_PUBLIC_IP',presence_id='user_n7sn94mefq@AUTH_REALM.MY_AUTH_REALM_DOMAIN.NET',absolute_codec_string='^^:G722:PCMU:PCMA',leg_timeout='20',effective_callee_id_number='MY_CALLER_ID_NUMBER',effective_callee_id_name='MY_CALLER_ID_NAME',origination_callee_id_number='MY_CALLER_ID_NUMBER',origination_callee_id_name='MY_CALLER_ID_NAME',ecallmgr_Realm='AUTH_REALM.MY_AUTH_REALM_DOMAIN.NET',ecallmgr_Username='user_n7sn94mefq']sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031;transport=udp;fs_path=sip:WHAPPS_SERVER_PUBLIC_IP:7000;lr;received='sip:MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031;transport=udp',[ecallmgr_Authorizing-ID='c9cf945b7cd3810717bfef04f41d6033',ecallmgr_Owner-ID='9a00bda774d5ad8f04eaa0c63b4f43fd',ecallmgr_Account-ID='ad9d5ba969687ae92dd65a8b86f72d8a',sdp_secure_savp_only='false',sip_invite_domain='EDGE_SBC_PUBLIC_IP',presence_id='user_w7ugp8@AUTH_REALM.MY_AUTH_REALM_DOMAIN.NET',absolute_codec_string='^^:G722:PCMU:PCMA',leg_timeout='20',effective_callee_id_number='MY_CALLER_ID_NUMBER',effective_callee_id_name='MY_CALLER_ID_NAME',origination_callee_id_number='MY_CALLER_ID_NUMBER',origination_callee_id_name='MY_CALLER_ID_NAME',ecallmgr_Realm='AUTH_REALM.MY_AUTH_REALM_DOMAIN.NET',ecallmgr_Username='user_w7ugp8']sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144;transport=udp;fs_path=sip:WHAPPS_SERVER_PUBLIC_IP:7000;lr;received='sip:POLYCOM_PUBLIC_IP:1144;transport=udp')

2015-01-16 00:33:49.544379 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 EXPORTING[export_vars] [ecallmgr_Bridge-ID]=[386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP] to event

2015-01-16 00:33:49.544379 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[ecal...@APP01.MY_DOMAIN.NET] to event

2015-01-16 00:33:49.544379 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 EXPORTING[export_vars] [sip_redirect_context]=[context_2] to event

2015-01-16 00:33:49.544379 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 EXPORTING[export_vars] [ecallmgr_Inception]=[14358797447@EDGE_SBC_PUBLIC_IP] to event

2015-01-16 00:33:49.544379 [DEBUG] switch_ivr_originate.c:2079 Parsing global variables

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [call_timeout]=[20]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [originate_timeout]=[20]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [local_var_clobber]=[true]

2015-01-16 00:33:49.544379 [DEBUG] switch_ivr_originate.c:2526 Parsing session specific variables

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [ecallmgr_Authorizing-ID]=[31ce66a0d9f6b9bc73bb0cbeb7e6bc14]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [ecallmgr_Owner-ID]=[9a00bda774d5ad8f04eaa0c63b4f43fd]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [ecallmgr_Account-ID]=[ad9d5ba969687ae92dd65a8b86f72d8a]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [sdp_secure_savp_only]=[false]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [sip_invite_domain]=[EDGE_SBC_PUBLIC_IP]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [presence_id]=[user_n7sn94mefq@AUTH_REALM.MY_AUTH_REALM_DOMAIN.NET]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [absolute_codec_string]=[^^:G722:PCMU:PCMA]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [leg_timeout]=[20]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [effective_callee_id_number]=[MY_CALLER_ID_NUMBER]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [effective_callee_id_name]=[MY_CALLER_ID_NAME]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [origination_callee_id_number]=[MY_CALLER_ID_NUMBER]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [origination_callee_id_name]=[MY_CALLER_ID_NAME]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [ecallmgr_Realm]=[AUTH_REALM.MY_AUTH_REALM_DOMAIN.NET]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [ecallmgr_Username]=[user_n7sn94mefq]

2015-01-16 00:33:49.544379 [NOTICE] switch_channel.c:1055 New Channel sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 [56e4f52a-9d17-11e4-82d4-3599fa757155]

2015-01-16 00:33:49.544379 [DEBUG] mod_sofia.c:4637 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State Change CS_NEW -> CS_INIT

2015-01-16 00:33:49.544379 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 [BREAK]

2015-01-16 00:33:49.544379 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 5662

2015-01-16 00:33:49.544379 [DEBUG] switch_ivr_originate.c:2820 sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 Setting leg timeout to 20

2015-01-16 00:33:49.544379 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 5662

2015-01-16 00:33:49.544379 [DEBUG] switch_ivr_originate.c:2526 Parsing session specific variables

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) Running State Change CS_INIT

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [ecallmgr_Authorizing-ID]=[c9cf945b7cd3810717bfef04f41d6033]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [ecallmgr_Owner-ID]=[9a00bda774d5ad8f04eaa0c63b4f43fd]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [ecallmgr_Account-ID]=[ad9d5ba969687ae92dd65a8b86f72d8a]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [sdp_secure_savp_only]=[false]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [sip_invite_domain]=[EDGE_SBC_PUBLIC_IP]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [presence_id]=[user_w7ugp8@AUTH_REALM.MY_AUTH_REALM_DOMAIN.NET]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [absolute_codec_string]=[^^:G722:PCMU:PCMA]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [leg_timeout]=[20]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [effective_callee_id_number]=[MY_CALLER_ID_NUMBER]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [effective_callee_id_name]=[MY_CALLER_ID_NAME]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [origination_callee_id_number]=[MY_CALLER_ID_NUMBER]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [origination_callee_id_name]=[MY_CALLER_ID_NAME]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [ecallmgr_Realm]=[AUTH_REALM.MY_AUTH_REALM_DOMAIN.NET]

2015-01-16 00:33:49.544379 [DEBUG] switch_event.c:1688 Parsing variable [ecallmgr_Username]=[user_w7ugp8]

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:512 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State INIT

2015-01-16 00:33:49.544379 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 SOFIA INIT

2015-01-16 00:33:49.544379 [NOTICE] switch_channel.c:1055 New Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [56e50c72-9d17-11e4-82da-3599fa757155]

2015-01-16 00:33:49.544379 [DEBUG] mod_sofia.c:4637 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State Change CS_NEW -> CS_INIT

2015-01-16 00:33:49.544379 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:49.544379 [DEBUG] sofia_glue.c:1203 sip:WHAPPS_SERVER_PUBLIC_IP:7000 Setting proxy route to sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031

2015-01-16 00:33:49.544379 [DEBUG] sofia_glue.c:1232 sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 sending invite version: 1.4.14 64bit

Local SDP:

v=0

o=FreeSWITCH 1421336109 1421336110 IN IP4 FREESWITCH_SERVER_PUBLIC_IP

s=FreeSWITCH

c=IN IP4 FREESWITCH_SERVER_PUBLIC_IP

t=0 0

m=audio 32320 RTP/AVP 9 0 8 101 13

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-16

a=ptime:20

a=sendrecv

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 Standard INIT

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State Change CS_INIT -> CS_ROUTING

2015-01-16 00:33:49.544379 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 [BREAK]

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:512 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State INIT going to sleep

2015-01-16 00:33:49.544379 [DEBUG] switch_ivr_originate.c:2820 sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 Setting leg timeout to 20

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) Running State Change CS_ROUTING

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) Running State Change CS_INIT

2015-01-16 00:33:49.544379 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 [BREAK]

2015-01-16 00:33:49.544379 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 entering state [calling][0]

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:528 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State ROUTING

2015-01-16 00:33:49.544379 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 SOFIA ROUTING

2015-01-16 00:33:49.544379 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State Change CS_ROUTING -> CS_CONSUME_MEDIA

2015-01-16 00:33:49.544379 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 [BREAK]

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:528 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State ROUTING going to sleep

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:512 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State INIT

2015-01-16 00:33:49.544379 [DEBUG] mod_sofia.c:87 sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 SOFIA INIT

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) Running State Change CS_CONSUME_MEDIA

2015-01-16 00:33:49.544379 [DEBUG] sofia_glue.c:1203 sip:WHAPPS_SERVER_PUBLIC_IP:7000 Setting proxy route to sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144

2015-01-16 00:33:49.544379 [DEBUG] sofia_glue.c:1232 sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 sending invite version: 1.4.14 64bit

Local SDP:

v=0

o=FreeSWITCH 1421345269 1421345270 IN IP4 FREESWITCH_SERVER_PUBLIC_IP

s=FreeSWITCH

c=IN IP4 FREESWITCH_SERVER_PUBLIC_IP

t=0 0

m=audio 23160 RTP/AVP 9 0 8 101 13

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-16

a=ptime:20

a=sendrecv

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 Standard INIT

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State Change CS_INIT -> CS_ROUTING

2015-01-16 00:33:49.544379 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:547 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State CONSUME_MEDIA

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:512 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State INIT going to sleep

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:547 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State CONSUME_MEDIA going to sleep

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) Running State Change CS_ROUTING

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:528 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State ROUTING

2015-01-16 00:33:49.544379 [DEBUG] mod_sofia.c:123 sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 SOFIA ROUTING

2015-01-16 00:33:49.544379 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State Change CS_ROUTING -> CS_CONSUME_MEDIA

2015-01-16 00:33:49.544379 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:528 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State ROUTING going to sleep

2015-01-16 00:33:49.544379 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) Running State Change CS_CONSUME_MEDIA

2015-01-16 00:33:49.544379 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 entering state [calling][0]

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:547 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State CONSUME_MEDIA

2015-01-16 00:33:49.544379 [DEBUG] switch_core_state_machine.c:547 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State CONSUME_MEDIA going to sleep

2015-01-16 00:33:49.544379 [DEBUG] kazoo_node.c:1100 Sent erlang message to ecal...@APP01.MY_DOMAIN.NET <1.10527.12>

2015-01-16 00:33:49.544379 [INFO] kazoo_node.c:625 exec: uuid_setvar_multi(56e4f52a-9d17-11e4-82d4-3599fa757155 ecallmgr_Channel-Authorized=true;ecallmgr_Account-ID=ad9d5ba969687ae92dd65a8b86f72d8a)

2015-01-16 00:33:49.564283 [INFO] kazoo_node.c:625 exec: uuid_setvar_multi(56e50c72-9d17-11e4-82da-3599fa757155 ecallmgr_Channel-Authorized=true;ecallmgr_Account-ID=ad9d5ba969687ae92dd65a8b86f72d8a)

2015-01-16 00:33:49.564283 [DEBUG] kazoo_node.c:1100 Sent erlang message to ecal...@APP01.MY_DOMAIN.NET <1.10580.12>

2015-01-16 00:33:49.644370 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:49.644370 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 entering state [proceeding][180]

2015-01-16 00:33:49.644370 [NOTICE] sofia.c:6717 Ring-Ready sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144!

2015-01-16 00:33:49.644370 [DEBUG] switch_channel.c:3277 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) Callstate Change DOWN -> RINGING

2015-01-16 00:33:49.644370 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 [BREAK]

2015-01-16 00:33:49.644370 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 entering state [proceeding][180]

2015-01-16 00:33:49.644370 [NOTICE] sofia.c:6717 Ring-Ready sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031!

2015-01-16 00:33:49.644370 [DEBUG] switch_channel.c:3277 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) Callstate Change DOWN -> RINGING

2015-01-16 00:33:49.644370 [INFO] switch_ivr_originate.c:1192 Sending early media

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:115:32000:20:48000:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:107:16000:20:32000:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3670 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G729:18:8000:20:8000:1]/[G7221:115:32000:20:48000:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G729:18:8000:20:8000:1]/[G7221:107:16000:20:32000:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G729:18:8000:20:8000:1]/[SPEEX:99:8000:20:24600:1]

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3531 Set telephone-event payload to 101

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:2473 Set Codec sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 PCMU/8000 20 ms 160 samples 64000 bits 1 channels

2015-01-16 00:33:49.644370 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Original read codec set to PCMU:0

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:3861 Set 2833 dtmf send/recv payload to 101

2015-01-16 00:33:49.644370 [DEBUG] switch_core_media.c:5111 AUDIO RTP [sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060] FREESWITCH_SERVER_PUBLIC_IP port 27816 -> TERMINATION_PROVIDERS_MEDIA_IP port 5764 codec: 0 ms: 20

2015-01-16 00:33:49.644370 [DEBUG] switch_rtp.c:3521 Starting timer [soft] 160 bytes per 20ms

2015-01-16 00:33:49.664350 [DEBUG] switch_core_media.c:5409 Set 2833 dtmf send payload to 101

2015-01-16 00:33:49.664350 [DEBUG] switch_core_media.c:5415 Set 2833 dtmf receive payload to 101

2015-01-16 00:33:49.664350 [NOTICE] sofia_media.c:92 Pre-Answer sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060!

2015-01-16 00:33:49.664350 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4115

2015-01-16 00:33:49.664350 [DEBUG] switch_channel.c:3399 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Callstate Change RINGING -> EARLY

2015-01-16 00:33:49.664350 [DEBUG] mod_sofia.c:2249 Ring SDP:

v=0

o=FreeSWITCH 1421340613 1421340614 IN IP4 FREESWITCH_SERVER_PUBLIC_IP

s=FreeSWITCH

c=IN IP4 FREESWITCH_SERVER_PUBLIC_IP

t=0 0

m=audio 27816 RTP/AVP 0 101

a=rtpmap:0 PCMU/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=ptime:20

a=sendrecv

2015-01-16 00:33:49.664350 [DEBUG] switch_core_session.c:908 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:49.664350 [DEBUG] switch_ivr_originate.c:1249 Raw Codec Activation Success L16@8000hz 1 channel 20ms

2015-01-16 00:33:49.664350 [DEBUG] switch_core_codec.c:221 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Push codec L16:70

2015-01-16 00:33:49.664350 [DEBUG] switch_ivr_originate.c:1317 Play Ringback Tone [%(2000,4000,440,480)]

2015-01-16 00:33:49.664350 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:49.684350 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 entering state [early][183]

2015-01-16 00:33:49.764444 [DEBUG] kazoo_node.c:1100 Sent erlang message to ecal...@APP01.MY_DOMAIN.NET <1.10583.12>

2015-01-16 00:33:50.044396 [DEBUG] switch_rtp.c:5823 Correct ip/port confirmed.

2015-01-16 00:33:50.944383 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:50.944383 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 entering state [completing][200]

2015-01-16 00:33:50.944383 [DEBUG] sofia.c:6624 Remote SDP:

v=0

o=- 1421368430 1421368430 IN IP4 POLYCOM_PUBLIC_IP

s=Polycom IP Phone

c=IN IP4 POLYCOM_PUBLIC_IP

t=0 0

m=audio 2236 RTP/AVP 9 101

a=rtpmap:9 G722/8000

a=rtpmap:101 telephone-event/8000

a=oldmediaip:192.168.1.165

2015-01-16 00:33:50.944383 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:50.944383 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 entering state [ready][200]

2015-01-16 00:33:50.944383 [DEBUG] sofia.c:6621 Duplicate SDP

v=0

o=- 1421368430 1421368430 IN IP4 POLYCOM_PUBLIC_IP

s=Polycom IP Phone

c=IN IP4 POLYCOM_PUBLIC_IP

t=0 0

m=audio 2236 RTP/AVP 9 101

a=rtpmap:9 G722/8000

a=rtpmap:101 telephone-event/8000

a=oldmediaip:192.168.1.165

2015-01-16 00:33:50.944383 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]

2015-01-16 00:33:50.944383 [DEBUG] switch_core_media.c:3670 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match

2015-01-16 00:33:50.944383 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]

2015-01-16 00:33:50.944383 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]

2015-01-16 00:33:50.944383 [DEBUG] switch_core_media.c:3531 Set telephone-event payload to 101

2015-01-16 00:33:50.944383 [DEBUG] switch_core_media.c:2473 Set Codec sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 G722/8000 20 ms 160 samples 64000 bits 1 channels

2015-01-16 00:33:50.944383 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 Original read codec set to G722:9

2015-01-16 00:33:50.944383 [DEBUG] switch_core_media.c:3852 Set 2833 dtmf send payload to 101

2015-01-16 00:33:50.944383 [DEBUG] switch_core_media.c:5111 AUDIO RTP [sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144] FREESWITCH_SERVER_PUBLIC_IP port 23160 -> POLYCOM_PUBLIC_IP port 2236 codec: 9 ms: 20

2015-01-16 00:33:50.944383 [DEBUG] switch_rtp.c:3521 Starting timer [soft] 160 bytes per 20ms

2015-01-16 00:33:50.944383 [DEBUG] switch_core_media.c:5409 Set 2833 dtmf send payload to 101

2015-01-16 00:33:50.944383 [DEBUG] switch_core_media.c:5415 Set 2833 dtmf receive payload to 101

2015-01-16 00:33:50.944383 [DEBUG] switch_channel.c:3635 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:50.944383 [NOTICE] sofia.c:7476 Channel [sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144] has been answered

2015-01-16 00:33:50.944383 [DEBUG] switch_channel.c:3689 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) Callstate Change RINGING -> ACTIVE

2015-01-16 00:33:50.964361 [DEBUG] switch_core_codec.c:246 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Restore previous codec PCMU:0.

2015-01-16 00:33:50.964361 [NOTICE] switch_ivr_originate.c:3467 Hangup sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 [CS_CONSUME_MEDIA] [LOSE_RACE]

2015-01-16 00:33:50.964361 [DEBUG] switch_channel.c:3222 Send signal sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 [KILL]

2015-01-16 00:33:50.964361 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 [BREAK]

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) Running State Change CS_HANGUP

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:735 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) Callstate Change RINGING -> HANGUP

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:737 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State HANGUP

2015-01-16 00:33:50.964361 [DEBUG] mod_sofia.c:413 Channel sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 hanging up, cause: LOSE_RACE

2015-01-16 00:33:50.964361 [DEBUG] mod_sofia.c:782 Local SDP sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060:

v=0

o=FreeSWITCH 1421340613 1421340615 IN IP4 FREESWITCH_SERVER_PUBLIC_IP

s=FreeSWITCH

c=IN IP4 FREESWITCH_SERVER_PUBLIC_IP

t=0 0

m=audio 27816 RTP/AVP 0 101

a=rtpmap:0 PCMU/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=ptime:20

a=sendrecv

2015-01-16 00:33:50.964361 [DEBUG] switch_core_session.c:908 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:50.964361 [NOTICE] switch_ivr_originate.c:3494 Channel [sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060] has been answered

2015-01-16 00:33:50.964361 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:50.964361 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4102

2015-01-16 00:33:50.964361 [DEBUG] mod_sofia.c:478 Sending CANCEL to sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 Standard HANGUP, cause: LOSE_RACE

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:737 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State HANGUP going to sleep

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:504 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State Change CS_HANGUP -> CS_REPORTING

2015-01-16 00:33:50.964361 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 [BREAK]

2015-01-16 00:33:50.964361 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4102

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) Running State Change CS_REPORTING

2015-01-16 00:33:50.964361 [DEBUG] switch_channel.c:3689 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Callstate Change EARLY -> ACTIVE

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:823 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State REPORTING

2015-01-16 00:33:50.964361 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 entering state [completed][200]

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:104 sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 Standard REPORTING, cause: LOSE_RACE

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:823 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State REPORTING going to sleep

2015-01-16 00:33:50.964361 [DEBUG] switch_ivr_originate.c:3552 Originate Resulted in Success: [sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144]

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:498 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State Change CS_REPORTING -> CS_DESTROY

2015-01-16 00:33:50.964361 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 [BREAK]

2015-01-16 00:33:50.964361 [DEBUG] switch_core_session.c:1615 Session 461 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) Locked, Waiting on external entities

2015-01-16 00:33:50.964361 [NOTICE] switch_core_session.c:1633 Session 461 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) Ended

2015-01-16 00:33:50.964361 [NOTICE] switch_core_session.c:1637 Close Channel sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 [CS_DESTROY]

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:626 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) Running State Change CS_DESTROY

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:636 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State DESTROY

2015-01-16 00:33:50.964361 [DEBUG] mod_sofia.c:323 sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 SOFIA DESTROY

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:111 sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031 Standard DESTROY

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:636 (sofia/sipinterface_1/user_n7sn94mefq@MY_OTHER_RINGGROUP_PHONES_PUBLIC_IP:1031) State DESTROY going to sleep

2015-01-16 00:33:50.964361 [DEBUG] switch_core_session.c:908 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:50.964361 [DEBUG] switch_core_session.c:908 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:50.964361 [DEBUG] switch_ivr_bridge.c:1465 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA

2015-01-16 00:33:50.964361 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) Running State Change CS_EXCHANGE_MEDIA

2015-01-16 00:33:50.964361 [DEBUG] switch_core_state_machine.c:538 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State EXCHANGE_MEDIA

2015-01-16 00:33:50.964361 [DEBUG] mod_sofia.c:596 SOFIA EXCHANGE_MEDIA

2015-01-16 00:33:50.964361 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4748

2015-01-16 00:33:51.004284 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:51.024365 [NOTICE] switch_core_io.c:1287 Activating write resampler

2015-01-16 00:33:51.024365 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 entering state [ready][200]

2015-01-16 00:33:51.024365 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 entering state [received][100]

2015-01-16 00:33:51.024365 [DEBUG] sofia.c:6624 Remote SDP:

v=0

o=Sonus_UAC 25529 22049 IN IP4 TERMINATION_PROVIDERS_SIGNALING_IP

s=SIP Media Capabilities

c=IN IP4 TERMINATION_PROVIDERS_MEDIA_IP

t=0 0

m=audio 5764 RTP/AVP 0 101

a=rtpmap:0 PCMU/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

a=maxptime:20

2015-01-16 00:33:51.024365 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]

2015-01-16 00:33:51.024365 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:115:32000:20:48000:1]

2015-01-16 00:33:51.024365 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G7221:107:16000:20:32000:1]

2015-01-16 00:33:51.024365 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]

2015-01-16 00:33:51.024365 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]

2015-01-16 00:33:51.024365 [DEBUG] switch_core_media.c:3670 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match

2015-01-16 00:33:51.024365 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]

2015-01-16 00:33:51.024365 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]

2015-01-16 00:33:51.024365 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]

2015-01-16 00:33:51.024365 [DEBUG] switch_core_media.c:3531 Set telephone-event payload to 101

2015-01-16 00:33:51.024365 [DEBUG] switch_core_media.c:3861 Set 2833 dtmf send/recv payload to 101

2015-01-16 00:33:51.024365 [DEBUG] switch_core_media.c:5095 Audio params are unchanged for sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060.

2015-01-16 00:33:51.024365 [DEBUG] sofia.c:7260 Processing updated SDP

2015-01-16 00:33:51.024365 [DEBUG] switch_core_session.c:970 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:51.024365 [DEBUG] switch_core_session.c:970 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:51.024365 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:51.044345 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 entering state [completed][200]

2015-01-16 00:33:51.044345 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:51.044345 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:33:51.064349 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 entering state [calling][0]

2015-01-16 00:33:51.064349 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 entering state [ready][200]

2015-01-16 00:33:51.064349 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:51.084387 [DEBUG] switch_rtp.c:5823 Correct ip/port confirmed.

2015-01-16 00:33:51.084387 [NOTICE] switch_core_io.c:1287 Activating write resampler

2015-01-16 00:33:51.084387 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 entering state [ready][200]

2015-01-16 00:33:51.084387 [DEBUG] sofia.c:6621 Duplicate SDP

v=0

o=- 1421368430 1421368430 IN IP4 POLYCOM_PUBLIC_IP

s=Polycom IP Phone

c=IN IP4 POLYCOM_PUBLIC_IP

t=0 0

m=audio 2236 RTP/AVP 9 101

a=rtpmap:9 G722/8000

a=rtpmap:101 telephone-event/8000

a=oldmediaip:192.168.1.165

2015-01-16 00:33:51.084387 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]

2015-01-16 00:33:51.084387 [DEBUG] switch_core_media.c:3670 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match

2015-01-16 00:33:51.084387 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]

2015-01-16 00:33:51.084387 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]

2015-01-16 00:33:51.084387 [DEBUG] switch_core_media.c:3531 Set telephone-event payload to 101

2015-01-16 00:33:51.084387 [DEBUG] switch_core_media.c:3852 Set 2833 dtmf send payload to 101

2015-01-16 00:33:51.084387 [DEBUG] sofia.c:7319 Processing updated SDP

2015-01-16 00:33:51.084387 [DEBUG] switch_core_media.c:5095 Audio params are unchanged for sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144.

2015-01-16 00:33:53.764398 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:53.784390 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 entering state [received][100]

2015-01-16 00:33:53.784390 [DEBUG] sofia.c:6624 Remote SDP:

v=0

o=- 1421368430 1421368431 IN IP4 192.168.1.165

s=Polycom IP Phone

c=IN IP4 0.0.0.0

t=0 0

m=audio 2236 RTP/AVP 9 101

a=rtpmap:9 G722/8000

a=rtpmap:101 telephone-event/8000

2015-01-16 00:33:53.784390 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]

2015-01-16 00:33:53.784390 [DEBUG] switch_core_media.c:3670 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match

2015-01-16 00:33:53.784390 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]

2015-01-16 00:33:53.784390 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]

2015-01-16 00:33:53.784390 [DEBUG] switch_core_media.c:3531 Set telephone-event payload to 101

2015-01-16 00:33:53.784390 [DEBUG] switch_core_media.c:3852 Set 2833 dtmf send payload to 101

2015-01-16 00:33:53.784390 [DEBUG] switch_core_media.c:5100 Audio params changed for sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 from POLYCOM_PUBLIC_IP:2236 to 0.0.0.0:2236

2015-01-16 00:33:53.784390 [DEBUG] switch_core_media.c:5111 AUDIO RTP [sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144] FREESWITCH_SERVER_PUBLIC_IP port 23160 -> 0.0.0.0 port 2236 codec: 9 ms: 20

2015-01-16 00:33:53.784390 [DEBUG] switch_core_media.c:5140 AUDIO RTP CHANGING DEST TO: [0.0.0.0:2236]

2015-01-16 00:33:53.784390 [DEBUG] sofia.c:7260 Processing updated SDP

2015-01-16 00:33:53.784390 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:53.804381 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 entering state [completed][200]

2015-01-16 00:33:53.824397 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:33:53.844397 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 entering state [ready][200]

2015-01-16 00:33:53.844397 [DEBUG] sofia.c:6624 Remote SDP:

v=0

o=- 1421368430 1421368430 IN IP4 POLYCOM_PUBLIC_IP

s=Polycom IP Phone

c=IN IP4 POLYCOM_PUBLIC_IP

t=0 0

m=audio 2236 RTP/AVP 9 101

a=rtpmap:9 G722/8000

a=rtpmap:101 telephone-event/8000

a=oldmediaip:192.168.1.165

2015-01-16 00:33:53.844397 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]

2015-01-16 00:33:53.844397 [DEBUG] switch_core_media.c:3670 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match

2015-01-16 00:33:53.844397 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]

2015-01-16 00:33:53.844397 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]

2015-01-16 00:33:53.844397 [DEBUG] switch_core_media.c:3531 Set telephone-event payload to 101

2015-01-16 00:33:53.844397 [DEBUG] switch_core_media.c:3852 Set 2833 dtmf send payload to 101

2015-01-16 00:33:53.844397 [DEBUG] sofia.c:7319 Processing updated SDP

2015-01-16 00:33:53.844397 [DEBUG] switch_core_media.c:5100 Audio params changed for sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 from 0.0.0.0:2236 to POLYCOM_PUBLIC_IP:2236

2015-01-16 00:33:53.844397 [DEBUG] switch_core_media.c:5111 AUDIO RTP [sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144] FREESWITCH_SERVER_PUBLIC_IP port 23160 -> POLYCOM_PUBLIC_IP port 2236 codec: 9 ms: 20

2015-01-16 00:33:53.844397 [DEBUG] switch_core_media.c:5140 AUDIO RTP CHANGING DEST TO: [POLYCOM_PUBLIC_IP:2236]

2015-01-16 00:34:00.204512 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:34:00.224395 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 entering state [received][100]

2015-01-16 00:34:00.224395 [DEBUG] sofia.c:6624 Remote SDP:

v=0

o=- 1421368430 1421368432 IN IP4 POLYCOM_PUBLIC_IP

s=Polycom IP Phone

c=IN IP4 POLYCOM_PUBLIC_IP

t=0 0

m=audio 2236 RTP/AVP 9 101

a=rtpmap:9 G722/8000

a=rtpmap:101 telephone-event/8000

a=oldmediaip:192.168.1.165

2015-01-16 00:34:00.224395 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]

2015-01-16 00:34:00.224395 [DEBUG] switch_core_media.c:3670 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match

2015-01-16 00:34:00.224395 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]

2015-01-16 00:34:00.224395 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]

2015-01-16 00:34:00.224395 [DEBUG] switch_core_media.c:3531 Set telephone-event payload to 101

2015-01-16 00:34:00.224395 [DEBUG] switch_core_media.c:3852 Set 2833 dtmf send payload to 101

2015-01-16 00:34:00.224395 [DEBUG] switch_core_media.c:5095 Audio params are unchanged for sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144.

2015-01-16 00:34:00.224395 [DEBUG] sofia.c:7260 Processing updated SDP

2015-01-16 00:34:00.224395 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:34:00.224395 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 entering state [completed][200]

2015-01-16 00:34:00.264511 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:34:00.284529 [DEBUG] sofia.c:6614 Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 entering state [ready][200]

2015-01-16 00:34:00.284529 [DEBUG] sofia.c:6624 Remote SDP:

v=0

o=- 1421368430 1421368430 IN IP4 POLYCOM_PUBLIC_IP

s=Polycom IP Phone

c=IN IP4 POLYCOM_PUBLIC_IP

t=0 0

m=audio 2236 RTP/AVP 9 101

a=rtpmap:9 G722/8000

a=rtpmap:101 telephone-event/8000

a=oldmediaip:192.168.1.165

2015-01-16 00:34:00.284529 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]

2015-01-16 00:34:00.284529 [DEBUG] switch_core_media.c:3670 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match

2015-01-16 00:34:00.284529 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]

2015-01-16 00:34:00.284529 [DEBUG] switch_core_media.c:3615 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]

2015-01-16 00:34:00.284529 [DEBUG] switch_core_media.c:3531 Set telephone-event payload to 101

2015-01-16 00:34:00.284529 [DEBUG] switch_core_media.c:3852 Set 2833 dtmf send payload to 101

2015-01-16 00:34:00.284529 [DEBUG] sofia.c:7319 Processing updated SDP

2015-01-16 00:34:00.284529 [DEBUG] switch_core_media.c:5095 Audio params are unchanged for sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144.

2015-01-16 00:34:00.344516 [DEBUG] switch_rtp.c:5823 Correct ip/port confirmed.

2015-01-16 00:34:03.864525 [DEBUG] switch_core_session.c:1053 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:34:03.884524 [DEBUG] switch_ivr_bridge.c:579 sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 ending bridge by request from write function

2015-01-16 00:34:03.884524 [DEBUG] switch_ivr_bridge.c:660 BRIDGE THREAD DONE [sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060]

2015-01-16 00:34:03.884524 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:34:03.884524 [NOTICE] sofia.c:952 Hangup sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]

2015-01-16 00:34:03.884524 [DEBUG] switch_channel.c:3222 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [KILL]

2015-01-16 00:34:03.884524 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:34:03.884524 [DEBUG] switch_ivr_bridge.c:660 BRIDGE THREAD DONE [sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144]

2015-01-16 00:34:03.884524 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:538 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State EXCHANGE_MEDIA going to sleep

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) Running State Change CS_HANGUP

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:735 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) Callstate Change ACTIVE -> HANGUP

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:737 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State HANGUP

2015-01-16 00:34:03.884524 [DEBUG] mod_sofia.c:413 Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 hanging up, cause: NORMAL_CLEARING

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 Standard HANGUP, cause: NORMAL_CLEARING

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:737 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State HANGUP going to sleep

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:504 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State Change CS_HANGUP -> CS_REPORTING

2015-01-16 00:34:03.884524 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) Running State Change CS_REPORTING

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:823 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State REPORTING

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:104 sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 Standard REPORTING, cause: NORMAL_CLEARING

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:823 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State REPORTING going to sleep

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:498 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State Change CS_REPORTING -> CS_DESTROY

2015-01-16 00:34:03.884524 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [BREAK]

2015-01-16 00:34:03.884524 [DEBUG] switch_core_session.c:1615 Session 462 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) Locked, Waiting on external entities

2015-01-16 00:34:03.884524 [DEBUG] switch_core_session.c:908 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:34:03.884524 [NOTICE] switch_ivr_bridge.c:1608 Hangup sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [CS_EXECUTE] [NORMAL_CLEARING]

2015-01-16 00:34:03.884524 [DEBUG] switch_channel.c:3222 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [KILL]

2015-01-16 00:34:03.884524 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:34:03.884524 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 4835

2015-01-16 00:34:03.884524 [NOTICE] switch_core_session.c:1633 Session 462 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) Ended

2015-01-16 00:34:03.884524 [NOTICE] switch_core_session.c:1637 Close Channel sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 [CS_DESTROY]

2015-01-16 00:34:03.884524 [DEBUG] switch_core_session.c:2893 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:535 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State EXECUTE going to sleep

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Running State Change CS_HANGUP

2015-01-16 00:34:03.884524 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 6413

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:626 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) Running State Change CS_DESTROY

2015-01-16 00:34:03.884524 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 6413

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:735 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Callstate Change ACTIVE -> HANGUP

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:636 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State DESTROY

2015-01-16 00:34:03.884524 [DEBUG] mod_sofia.c:323 sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 SOFIA DESTROY

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:111 sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144 Standard DESTROY

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:636 (sofia/sipinterface_1/user_w7ugp8@POLYCOM_PUBLIC_IP:1144) State DESTROY going to sleep

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:737 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State HANGUP

2015-01-16 00:34:03.884524 [DEBUG] mod_sofia.c:407 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Overriding SIP cause 480 with 200 from the other leg

2015-01-16 00:34:03.884524 [DEBUG] mod_sofia.c:413 Channel sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 hanging up, cause: NORMAL_CLEARING

2015-01-16 00:34:03.884524 [DEBUG] mod_sofia.c:467 Sending BYE to sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Standard HANGUP, cause: NORMAL_CLEARING

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:737 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State HANGUP going to sleep

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:504 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State Change CS_HANGUP -> CS_REPORTING

2015-01-16 00:34:03.884524 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:472 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Running State Change CS_REPORTING

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:823 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State REPORTING

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:104 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Standard REPORTING, cause: NORMAL_CLEARING

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:823 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State REPORTING going to sleep

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:498 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State Change CS_REPORTING -> CS_DESTROY

2015-01-16 00:34:03.884524 [DEBUG] switch_core_session.c:1388 Send signal sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [BREAK]

2015-01-16 00:34:03.884524 [DEBUG] switch_core_session.c:1615 Session 460 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Locked, Waiting on external entities

2015-01-16 00:34:03.884524 [NOTICE] switch_core_session.c:1633 Session 460 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Ended

2015-01-16 00:34:03.884524 [NOTICE] switch_core_session.c:1637 Close Channel sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 [CS_DESTROY]

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:626 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) Running State Change CS_DESTROY

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:636 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State DESTROY

2015-01-16 00:34:03.884524 [DEBUG] mod_sofia.c:323 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 SOFIA DESTROY

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:111 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 Standard DESTROY

2015-01-16 00:34:03.884524 [DEBUG] switch_core_state_machine.c:636 (sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060) State DESTROY going to sleep

2015-01-16 00:34:03.884524 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 5082

/exit

J. Erickson

unread,

Jan 15, 2015, 7:59:33 PM1/15/15

to 2600h...@googlegroups.com

Although it's probably easy to find for the experts, though I should post the timestamp of roundabout when I press the Hold softkey: 2015-01-16 00:33:53

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 log(NOTICE log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|ecallmgr@APP01.MY_DOMAIN.NET won call control)
2015-01-16 00:33:48.924397 [NOTICE] mod_dptools.c:1650 log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|ecallmgr@APP01.MY_DOMAIN.NET won call control
EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 export(ecallmgr_Ecallmgr-Node=ecal...@APP01.MY_DOMAIN.NET)
2015-01-16 00:33:48.924397 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [ecallmgr_Ecallmgr-Node]=[ecallm...@APP01.MY_DOMAIN.NET]

2015-01-16 00:33:49.544379 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[ecallm...@APP01.MY_DOMAIN.NET] to event

/exit

J. Erickson

unread,

Jan 23, 2015, 2:38:22 AM1/23/15

to 2600h...@googlegroups.com

Downgrading FreeSwitch from the 1.4.14 Staging version to the latest 1.4.7 release in the new Stable repo resolved this issue.

On Thursday, January 15, 2015 at 5:46:19 PM UTC-7, J. Erickson wrote:

EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 log(NOTICE log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|ecallmgr@APP01.MY_DOMAIN.NET won call control)
2015-01-16 00:33:48.924397 [NOTICE] mod_dptools.c:1650 log|386707629_28811789@TERMINATION_PROVIDERS_SIGNALING_IP|ecallmgr@APP01.MY_DOMAIN.NET won call control
EXECUTE sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 export(ecallmgr_Ecallmgr-Node=ecal...@APP01.MY_DOMAIN.NET)
2015-01-16 00:33:48.924397 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [ecallmgr_Ecallmgr-Node]=[ecallm...@APP01.MY_DOMAIN.NET]

2015-01-16 00:33:49.544379 [DEBUG] switch_channel.c:1201 sofia/sipinterface_1/MY_CELL_NUMBER@TERMINATION_PROVIDERS_SIGNALING_IP:5060 EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[ecallm...@APP01.MY_DOMAIN.NET] to event