Outbound calls through offnet fail progress timeout

[Alocaurd]

I have a 4 server deployment setup for testing: 2 freeswitch servers and 2 kamailio server. I have a gateway setup with voip.ms and flowroute and have tested with IP auth and with registration. I have left freesitech on port 11000 and also changed it to 5060. I have tested with manually making the gateway file on the FS servers as well, but have removed them as they didnt work.

Please see a dump from one FS server when a phone call was made. IPs and whatnot have been removed.

http://pastebin.com/QvWWcbdr

[Mikko]

I'm having the same problem and I'm stumped.

I'm getting progress_timeout hangup on outgoing calls though our offnet carrier.
Freeswitch's logs show that the 183 Session Progress message is received from the carrier. It even parses the SDP.
Ngrep show that the moment the 183 is received, the carrier starts sending RTP packets to the port advertised in the INVITE, so early media is working.

The freeswitch is running on a VM that uses an internal IP and binding to public IP.

We've taken care of the IP mismatches on the carrier side (we are routing the calls though kamailio servers, different servers than Kazoo's kamailios).

The alert e-mail tells that hangup_cause: PROGRESS_TIMEOUT

It also says ringing_seconds: 0, even though the phone had time to ring for 2-3 seconds.

If I answer the call within the time that it is ringing, the call works fine. It doesn't timeout.

Here is our offnet DB doc for the carrier:

{
 "_id": "XXX-carrier",
 "_rev": "13-23f6ab6842f1c0ef7bd4ef9d26fb2ff8",
 "weight_cost": "50",
 "enabled": true,
 "gateways": [
  …
  {
   "prefix": "",
   "codecs": [ "PCMA", "PCMU" ],
   "server": "###GATEWAY2###",
   "username": "",
   "password": "",
   "realm": "###GATEWAY2###",
   "format_from_uri": false,
   "suffix": "",
   "progress_timeout": "10",
   "enabled": true,
   "custom_sip_headers": {},
   "invite_format": "route",
   "endpoint_type": "sip",
   "channel_selection": "ascending",
   "skype_rr": true,
   "emergency": false
  }
 ],
 "rules": [ ".*" ],
 "caller_id_options": {
  "type": "external"
 },
 "flags": [],
 "emergency": false,
 "grace_period": 5,
 "media": {
  "audio": {
   "codecs": [ "PCMA" ]
  },
  "video": {
   "codecs": []
  },
  "fax_option": true
 },
 "pvt_type": "resource",
 "pvt_vsn": "1",
 "pvt_account_id": "admin account number",
 "pvt_account_db": "account%2Ff3%2F5d%admin account number",
 "pvt_created": 63587176168,
 "pvt_modified": 63587176168
}

Here is an abridged version of freeswitch's logs:

send 1173 bytes to udp/[###GATEWAY2###]:5060 at 21:21:55.821345:

…

[we send INVITE to carrier]

…

2016-10-06 21:21:55.806008 [DEBUG] sofia.c:6962 Channel sofia/sipinterface_1/0451234567@###GATEWAY2### entering state [calling][0]

…

[we receive 100 trying from carrier]

…

2016-10-06 21:21:55.826039 [DEBUG] kazoo_node.c:1100 Sent erlang message to kazoo_apps@###KAZOO### <2.15283.184>

2016-10-06 21:21:55.826039 [INFO] kazoo_node.c:625 exec: kz_uuid_setvar_multi(83957722-64ec-46af-940e-9a225a218a04 ^^;ecallmgr_Account-ID=10649a107597e30ee5fcd1f743678ad1;ecallmgr_Reseller-ID=332cdb84b92ad1181a17a9ed90e7dfae;ecallmgr_Global-Resource=true;ecallmgr_Channel-Authorized=true)

2016-10-06 21:21:55.826039 [DEBUG] kazoo_node.c:1100 Sent erlang message to kazoo_apps@###KAZOO### <2.15319.184>

2016-10-06 21:21:55.826039 [INFO] kazoo_node.c:625 exec: kz_uuid_setvar_multi(83957722-64ec-46af-940e-9a225a218a04 ecallmgr_Call-Interaction-ID=63642997314-8a3a8214)

2016-10-06 21:21:56.026035 [DEBUG] kazoo_node.c:1100 Sent erlang message to kazoo_apps@###KAZOO### <2.15283.184>

…

[we receive 183 Session Progress from carrier]

…

2016-10-06 21:21:59.966016 [DEBUG] sofia.c:6962 Channel sofia/sipinterface_1/0451234567@###GATEWAY2### entering state [proceeding][183]

2016-10-06 21:21:59.966016 [DEBUG] sofia.c:6972 Remote SDP:

…

2016-10-06 21:22:06.006041 [NOTICE] switch_ivr_originate.c:322 Hangup sofia/sipinterface_1/0451234567@###GATEWAY2### [CS_CONSUME_MEDIA] [PROGRESS_TIMEOUT]

2016-10-06 21:22:06.006041 [DEBUG] switch_core_state_machine.c:543 (sofia/sipinterface_1/0451234567@###GATEWAY2###) Running State Change CS_HANGUP

2016-10-06 21:22:06.006041 [DEBUG] switch_core_state_machine.c:809 (sofia/sipinterface_1/0451234567@###GATEWAY2###) Callstate Change DOWN -> HANGUP

2016-10-06 21:22:06.006041 [DEBUG] switch_core_state_machine.c:811 (sofia/sipinterface_1/0451234567@###GATEWAY2###) State HANGUP

2016-10-06 21:22:06.006041 [DEBUG] mod_sofia.c:438 Channel sofia/sipinterface_1/0451234567@###GATEWAY2### hanging up, cause: PROGRESS_TIMEOUT

2016-10-06 21:22:06.006041 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/sipinterface_1/0451234567@###GATEWAY2###

2016-10-06 21:22:06.006041 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/0451234567@###GATEWAY2### Standard HANGUP, cause: PROGRESS_TIMEOUT

2016-10-06 21:22:06.006041 [DEBUG] switch_core_state_machine.c:811 (sofia/sipinterface_1/0451234567@###GATEWAY2###) State HANGUP going to sleep

2016-10-06 21:22:06.006041 [DEBUG] switch_core_state_machine.c:578 (sofia/sipinterface_1/0451234567@###GATEWAY2###) State Change CS_HANGUP -> CS_REPORTING

2016-10-06 21:22:06.006041 [DEBUG] switch_core_state_machine.c:543 (sofia/sipinterface_1/0451234567@###GATEWAY2###) Running State Change CS_REPORTING

2016-10-06 21:22:06.006041 [DEBUG] switch_core_state_machine.c:897 (sofia/sipinterface_1/0451234567@###GATEWAY2###) State REPORTING

2016-10-06 21:22:06.006041 [DEBUG] switch_core_state_machine.c:174 sofia/sipinterface_1/0451234567@###GATEWAY2### Standard REPORTING, cause: PROGRESS_TIMEOUT

2016-10-06 21:22:06.006041 [DEBUG] switch_core_state_machine.c:897 (sofia/sipinterface_1/0451234567@###GATEWAY2###) State REPORTING going to sleep

2016-10-06 21:22:06.006041 [DEBUG] switch_core_state_machine.c:569 (sofia/sipinterface_1/0451234567@###GATEWAY2###) State Change CS_REPORTING -> CS_DESTROY

2016-10-06 21:22:06.006041 [DEBUG] switch_core_session.c:1647 Session 52 (sofia/sipinterface_1/0451234567@###GATEWAY2###) Locked, Waiting on external entities

…

[we send 183 Session Progress to carrier]

…

Here is the log from Kazoo, it kind of long, but I'm not sure what parts to leave out:

Oct 6 21:21:54 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_endpoint:843 (<0.15198.184>) creating call forwarding endpoint

Oct 6 21:21:54 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_endpoint:1205 (<0.15198.184>) call forwarding endpoint to 0451234567

Oct 6 21:21:54 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_endpoint:826 (<0.15198.184>) failed to create endpoint: call_forward_substitute

Oct 6 21:21:54 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|cf_user:43 (<0.15198.184>) attempting 1 user devices with strategy simultaneous

Oct 6 21:21:54 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.15198.184>) published to callctl(amqp://user:pa...@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.15176.184>-6d559d63) via <0.24232.181>

Oct 6 21:21:54 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kapps_call_command:2471 (<0.15198.184>) waiting for bridge for 70000 ms

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_control:947 (<0.15176.184>) inserting at the tail of the control queue call command bridge

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_control:1037 (<0.15176.184>) executing call command 'bridge' ba19e0470bdd7e48821354914effda25

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_fs_bridge:49 (<0.15176.184>) creating bridge dialplan

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_config:185 (<0.15176.184>) looking up 'use_bypass_media_after_bridge' from sysconf

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_channel:159 (<0.937.0>) published to sysconf(amqp://user:pa...@127.0.0.1:5672) exchange (routing key sysconf.get) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_worker:563 (<0.937.0>) published request with msg id a1f6a675640f220478097cf9c9aa3cb8 for <0.15176.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|sysconf_get:29 (<0.15206.184>) received sysconf get for ecallmgr:use_bypass_media_after_bridge from kazoo_apps@###KAZOO###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|sysconf_get:34 (<0.15206.184>) sending reply for ecallmgr.use_bypass_media_after_bridge(kazoo_apps@###KAZOO###): false

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_channel:159 (<0.15206.184>) published to targeted(amqp://user:pa...@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.937.0>-f5433ed8) via <0.1103.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_worker:723 (<0.937.0>) response for msg id a1f6a675640f220478097cf9c9aa3cb8 took 7634 micro to return

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:815 (<0.1692.0>) storing {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:817 (<0.1692.0>) inserted {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:819 (<0.1692.0>) inserted origin pointers for {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:821 (<0.1692.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:596 (<0.15176.184>) building bridge endpoint: [<<"route">>,undefined,undefined,<<"+3589987654321">>,<<"loopback/0451234567">>,undefined,undefined]

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: set continue_on_fail=true

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export sip_redirect_context=context_2

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: set hangup_after_bridge=true

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export ecallmgr_Inception=${ecallmgr_Inception}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export ecallmgr_Call-Interaction-ID=${ecallmgr_Call-Interaction-ID}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: bridge {call_timeout=60,originate_timeout=60,outbound_redirect_fatal='false',ignore_early_media='true',local_var_clobber='true'}[presence_id='1000@demo1.###DOMAIN###',ignore_early_media='true',leg_timeout='60',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Call-Forward='true',ecallmgr_Authorizing-Type='device',loopback_bowout_on_execute='false',loopback_bowout='true',sdp_secure_savp_only='false',sip_invite_domain='###GATEWAY1###']loopback/0451234567

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: event Event-Name=CUSTOM,Event-Subclass=kazoo::masquerade,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=bridge

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: park

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(continue_on_fail=true)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(sip_redirect_context=context_2)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(hangup_after_bridge=true)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:710 (<0.15175.184>) publishing call event channel_execute_complete 'set(sip_redirect_context=context_2)' result: _none_

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE_COMPLETE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(ecallmgr_Inception=+3589987654321@###GATEWAY1###)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(ecallmgr_Call-Interaction-ID=63642997314-8a3a8214)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'bridge({call_timeout=60,originate_timeout=60,outbound_redirect_fatal='false',ignore_early_media='true',local_var_clobber='true'}[presence_id='1000@demo1.###DOMAIN###',ignore_early_media='true',leg_timeout='60',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Call-Forward='true',ecallmgr_Authorizing-Type='device',loopback_bowout_on_execute='false',loopback_bowout='true',sdp_secure_savp_only='false',sip_invite_domain='###GATEWAY1###']loopback/0451234567)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:710 (<0.15175.184>) publishing call event channel_execute_complete 'set(ecallmgr_Inception=+3589987654321@###GATEWAY1###)' result: _none_

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE_COMPLETE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:710 (<0.15175.184>) publishing call event channel_execute_complete 'set(ecallmgr_Call-Interaction-ID=63642997314-8a3a8214)' result: _none_

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE_COMPLETE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:706 (<0.15175.184>) publishing call event channel_progress_media

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_PROGRESS_MEDIA.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|ecallmgr_call_events:706 (<0.15220.184>) publishing call event channel_create

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_CREATE.d2f7fbbc-fdff-452b-b07c-c8dd7a53296a) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15220.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|ecallmgr_fs_authz:104 (<0.15220.184>) config ecallmgr.authz is disabled

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|ecallmgr_fs_authz:236 (<0.15220.184>) channel authorization succeeded, allowing call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:706 (<0.15221.184>) publishing call event channel_create

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_CREATE.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15221.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_authz:104 (<0.15221.184>) config ecallmgr.authz is disabled

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_authz:236 (<0.15221.184>) channel authorization succeeded, allowing call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:815 (<0.1692.0>) storing {authz_response,<<"d2f7fbbc-fdff-452b-b07c-c8dd7a53296a">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:817 (<0.1692.0>) inserted {authz_response,<<"d2f7fbbc-fdff-452b-b07c-c8dd7a53296a">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:819 (<0.1692.0>) inserted origin pointers for {authz_response,<<"d2f7fbbc-fdff-452b-b07c-c8dd7a53296a">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:821 (<0.1692.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:815 (<0.1692.0>) storing {authz_response,<<"d7062594-6c35-45ae-a74f-1117c8c269aa">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:817 (<0.1692.0>) inserted {authz_response,<<"d7062594-6c35-45ae-a74f-1117c8c269aa">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:819 (<0.1692.0>) inserted origin pointers for {authz_response,<<"d7062594-6c35-45ae-a74f-1117c8c269aa">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:821 (<0.1692.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|webhooks_channel_util:37 (<0.15223.184>) determined account id for CHANNEL_CREATE is 10649a107597e30ee5fcd1f743678ad1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|webhooks_channel_util:37 (<0.15224.184>) determined account id for CHANNEL_CREATE is 10649a107597e30ee5fcd1f743678ad1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_authz:104 (<0.15228.184>) config ecallmgr.authz is disabled

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|omnip_presence_amqp:189 (<0.15232.184>) received channel create, checking for presence subscribers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|omnip_presence_amqp:189 (<0.15231.184>) received channel create, checking for presence subscribers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|omnip_dialog_amqp:198 (<0.15236.184>) received channel create, checking for dialog subscribers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|omnip_dialog_amqp:198 (<0.15233.184>) received channel create, checking for dialog subscribers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.937.0>) published to callmgr(amqp://user:pa...@127.0.0.1:5672) exchange (routing key route.req.audio.demo1%2E###DOMAIN###.1000) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_route_req:35 (<0.15235.184>) received request adef768b-3924-4d59-914a-48e84ea738d8 asking if callflows can route this call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|stepswitch_inbound:30 (<0.15237.184>) fetch-id adef768b-3924-4d59-914a-48e84ea738d8 already has account-id 10649a107597e30ee5fcd1f743678ad1, skipping.

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|milliwatt_route_req:41 (<0.15234.184>) milliwatt does not know what to do with this!

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |2a9170c87de5ba0d|acdc_agent_manager:145 (<0.24506.144>) channel_create event

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ts_route_req:25 (<0.15242.184>) received request adef768b-3924-4d59-914a-48e84ea738d8 asking if trunkstore can route this call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|webhooks_channel_util:47 (<0.15223.184>) evt CHANNEL_CREATE for 10649a107597e30ee5fcd1f743678ad1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|webhooks_channel_util:49 (<0.15223.184>) no hooks to handle CHANNEL_CREATE for 10649a107597e30ee5fcd1f743678ad1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|webhooks_channel_util:47 (<0.15224.184>) evt CHANNEL_CREATE for 10649a107597e30ee5fcd1f743678ad1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|webhooks_channel_util:49 (<0.15224.184>) no hooks to handle CHANNEL_CREATE for 10649a107597e30ee5fcd1f743678ad1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_authz:236 (<0.15228.184>) channel authorization succeeded, allowing call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|omnip_presence_amqp:309 (<0.15232.184>) no presence subscriptions for 1000@demo1.###DOMAIN###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:815 (<0.1692.0>) storing {authz_response,<<"d7062594-6c35-45ae-a74f-1117c8c269aa">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:817 (<0.1692.0>) inserted {authz_response,<<"d7062594-6c35-45ae-a74f-1117c8c269aa">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:819 (<0.1692.0>) inserted origin pointers for {authz_response,<<"d7062594-6c35-45ae-a74f-1117c8c269aa">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:821 (<0.1692.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|omnip_presence_amqp:309 (<0.15231.184>) no presence subscriptions for 1000@demo1.###DOMAIN###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_authz:34 (<0.15228.184>) channel is authorized

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|omnip_dialog_amqp:370 (<0.15236.184>) no dialog subscriptions for 1000@demo1.###DOMAIN###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|omnip_dialog_amqp:370 (<0.15233.184>) no dialog subscriptions for 1000@demo1.###DOMAIN###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:563 (<0.937.0>) published request with msg id adef768b-3924-4d59-914a-48e84ea738d8 for <0.15225.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_flow:63 (<0.15235.184>) searching for callflow in account%2F10%2F64%2F9a107597e30ee5fcd1f743678ad1 to satisfy '0451234567'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |2a9170c87de5ba0d|acdc_agent_manager:145 (<0.24506.144>) channel_create event

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|acdc_agent_handler:255 (<0.15247.184>) new channel in acct 10649a107597e30ee5fcd1f743678ad1: from 1000 to 1000(0451234567)

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ts_route_req:37 (<0.15242.184>) call with fetch-id adef768b-3924-4d59-914a-48e84ea738d8 began on the network

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|acdc_agent_handler:255 (<0.15249.184>) new channel in acct 10649a107597e30ee5fcd1f743678ad1: from 1000 to 0451234567(0451234567)

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_control:695 (<0.15176.184>) added leg d2f7fbbc-fdff-452b-b07c-c8dd7a53296a to call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:706 (<0.15250.184>) publishing call event leg_created

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ts_callflow:54 (<0.15251.184>) request is not for a trunkstore account

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.927.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.LEG_CREATED.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1015.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.927.0>) published message 1475778115046007 for <0.15250.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|ecallmgr_fs_authz:34 (<0.15220.184>) channel is authorized

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.2310.0>) Supervisor ts_onnet_sup started ts_from_onnet:start_link({[{<<"Caller-ID-Number">>,<<"0912345678">>},{<<"Caller-ID-Name">>,<<"0912345678">>},{<<"Call-D...">>,...},...]}) at pid <0.15251.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |df071485f710dd99|kz_cache:815 (<0.1409.0>) storing {cf_patterns,<<"10649a107597e30ee5fcd1f743678ad1">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |df071485f710dd99|kz_cache:817 (<0.1409.0>) inserted {cf_patterns,<<"10649a107597e30ee5fcd1f743678ad1">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |df071485f710dd99|kz_cache:819 (<0.1409.0>) inserted origin pointers for {cf_patterns,<<"10649a107597e30ee5fcd1f743678ad1">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |df071485f710dd99|kz_cache:821 (<0.1409.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:815 (<0.1105.0>) storing {kzs_cache,<<"account%2F10%2F64%2F9a107597e30ee5fcd1f743678ad1">>,<<"ef3dc6fc6829f868dabb2094057ad412">>} for 900s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:817 (<0.1105.0>) inserted {kzs_cache,<<"account%2F10%2F64%2F9a107597e30ee5fcd1f743678ad1">>,<<"ef3dc6fc6829f868dabb2094057ad412">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:819 (<0.1105.0>) inserted origin pointers for {kzs_cache,<<"account%2F10%2F64%2F9a107597e30ee5fcd1f743678ad1">>,<<"ef3dc6fc6829f868dabb2094057ad412">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:821 (<0.1105.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_route_req:65 (<0.15235.184>) ignore preflow, not set

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_route_req:93 (<0.15235.184>) callflow ef3dc6fc6829f868dabb2094057ad412 in 10649a107597e30ee5fcd1f743678ad1 satisfies request

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_buckets:159 (<0.15235.184>) bucket (callflow 10649a107597e30ee5fcd1f743678ad1:ef3dc6fc6829f868dabb2094057ad412) missing, starting

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_buckets|kz_buckets:306 (<0.1155.0>) maybe starting token bucket for callflow, 10649a107597e30ee5fcd1f743678ad1:ef3dc6fc6829f868dabb2094057ad412 (100 at 10/second)

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_token_bucket|kz_token_bucket:173 (<0.15260.184>) starting token bucket with 100 max, filling at 10/second, in a block: true

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_buckets|kz_buckets:315 (<0.1155.0>) new bucket for callflow, 10649a107597e30ee5fcd1f743678ad1:ef3dc6fc6829f868dabb2094057ad412: <0.15260.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |00000000000|kz_token_bucket:248 (<0.15260.184>) updated name to {<<"callflow">>,<<"10649a107597e30ee5fcd1f743678ad1:ef3dc6fc6829f868dabb2094057ad412">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |00000000000|kz_token_bucket:203 (<0.15260.184>) consumed 5, 95 left

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_route_req:196 (<0.15235.184>) callflows knows how to route the call! sending park response

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |adef768b-3924-4d59-914a-48e84ea738d8|kz_amqp_channel:159 (<0.927.0>) published to targeted(amqp://user:pa...@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.937.0>-f5433ed8) via <0.1015.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |adef768b-3924-4d59-914a-48e84ea738d8|kz_amqp_worker:563 (<0.927.0>) published request with msg id d7062594-6c35-45ae-a74f-1117c8c269aa for <0.15235.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |adef768b-3924-4d59-914a-48e84ea738d8|kz_amqp_worker:723 (<0.937.0>) response for msg id adef768b-3924-4d59-914a-48e84ea738d8 took 25074 micro to return

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_router_util:108 (<0.15225.184>) received affirmative route response for request adef768b-3924-4d59-914a-48e84ea738d8

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_router_util:110 (<0.15225.184>) sending XML to frees...@10.0.0.1: <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}|kazoo_apps@###KAZOO### won call control"/><action application="export" data="ecallmgr_Ecallmgr-Node=kazoo_apps@###KAZOO###"/><condition field="variable_ecallmgr_Bridge-ID" expression="^$"><action application="export" data="ecallmgr_Bridge-ID=${UUID}" inline="true"/></condition><action application="set" data="ringback=%(2000,4000,440,480)"/><action application="set" data="transfer_ringback=%(2000,4000,440,480)"/><action application="kz_multiset" data="^^;ecallmgr_Call-Interaction-ID=63642997314-8a3a8214;ecallmgr_Fetch-ID=adef768b-3924-4d59-914a-48e84ea738d8;ecallmgr_Caller-Privacy-Number=false;ecallmgr_Caller-Privacy-Name=false;ecallmgr_Account-ID=10649a107597e30ee5fcd1f743678ad1;ecallmgr_Authorizing-ID=c7977a34493ff042b898cf74e32f2d94;ecallmgr_Authorizing-Type=device;ecallmgr_Bridge-ID=7a6c5abc4b42a4816961d5f91d425db2@###CALLER###;ecallmgr_Call-Forward=true;ecallmgr_Ecallmgr-Node=kazoo_apps@###KAZOO###;ecallmgr_Inception=+3589987654321@###GATEWAY1###;ecallmgr_Owner-ID=b27257e420981374d1f81671cfa39a0b;ecallmgr_CallFlow-ID=ef3dc6fc6829f868dabb2094057ad412"/><action application="park"/></condition></extension></context></section></document>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_authz:34 (<0.15221.184>) channel is authorized

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_control:695 (<0.15176.184>) added leg d7062594-6c35-45ae-a74f-1117c8c269aa to call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:706 (<0.15281.184>) publishing call event leg_created

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.LEG_CREATED.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15281.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_router_util:114 (<0.15225.184>) node frees...@10.0.0.1 accepted dialplan route response for request adef768b-3924-4d59-914a-48e84ea738d8

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_event_sup:38 (<0.15225.184>) starting event handler for frees...@10.0.0.1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|gen_listener:364 (<0.15279.184>) starting new gen_listener proc : ecallmgr_call_events

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:189 (<0.15279.184>) started call event publisher

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_amqp_assignments|kz_amqp_assignments:475 (<0.139.0>) assigned existing channel <0.24227.181> on amqp://user:pa...@127.0.0.1:5672 to new consumer <0.15279.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_amqp_assignments|kz_amqp_assignments:886 (<0.139.0>) registered handlers for channel <0.24227.181> to <0.15279.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|gen_listener:364 (<0.15283.184>) starting new gen_listener proc : ecallmgr_call_control

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_control:203 (<0.15283.184>) starting call control listener

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_amqp_assignments|kz_amqp_assignments:475 (<0.139.0>) assigned existing channel <0.24239.181> on amqp://user:pa...@127.0.0.1:5672 to new consumer <0.15283.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_amqp_assignments|kz_amqp_assignments:886 (<0.139.0>) registered handlers for channel <0.24239.181> to <0.15283.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_control:1182 (<0.15283.184>) binding to call d7062594-6c35-45ae-a74f-1117c8c269aa events on node frees...@10.0.0.1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:1131 (<0.15283.184>) channel started, let's connect

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_router_call:209 (<0.15225.184>) started event {ok,<0.15279.184>} and control {ok,<0.15283.184>} processes

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.15279.184>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.publisher_usurp.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.24227.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:1131 (<0.15279.184>) channel started, let's connect

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.15278.184>) Supervisor {<0.15278.184>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 127.0.0.1:50135 -> 127.0.0.1:5672">>,2200}) at pid <0.15284.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.15278.184>) Supervisor {<0.15278.184>,amqp_channel_sup} started amqp_channel:start_link(network, <0.145.0>, 2200, <0.15284.184>, {<<"client 127.0.0.1:50135 -> 127.0.0.1:5672">>,2200}) at pid <0.15275.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.15278.184>) Supervisor {<0.15278.184>,amqp_channel_sup} started rabbit_writer:start_link(#Port<0.3742>, 2200, 131072, rabbit_framing_amqp_0_9_1, <0.15275.184>, {<<"client 127.0.0.1:50135 -> 127.0.0.1:5672">>,2200}) at pid <0.15288.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.15291.184>) Supervisor {<0.15291.184>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 127.0.0.1:50135 -> 127.0.0.1:5672">>,2201}) at pid <0.15290.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.15291.184>) Supervisor {<0.15291.184>,amqp_channel_sup} started amqp_channel:start_link(network, <0.145.0>, 2201, <0.15290.184>, {<<"client 127.0.0.1:50135 -> 127.0.0.1:5672">>,2201}) at pid <0.15287.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.15291.184>) Supervisor {<0.15291.184>,amqp_channel_sup} started rabbit_writer:start_link(#Port<0.3742>, 2201, 131072, rabbit_framing_amqp_0_9_1, <0.15287.184>, {<<"client 127.0.0.1:50135 -> 127.0.0.1:5672">>,2201}) at pid <0.15276.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_amqp_assignments|kz_amqp_assignments:600 (<0.139.0>) added new channel <0.15275.184> on amqp://user:pa...@127.0.0.1:5672 to available pool

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_amqp_assignments|kz_amqp_assignments:600 (<0.139.0>) added new channel <0.15287.184> on amqp://user:pa...@127.0.0.1:5672 to available pool

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:302 (<0.15283.184>) declared queue kazoo_apps@###KAZOO###-<0.15283.184>-b29e89a2 via channel <0.24239.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:302 (<0.15279.184>) declared queue kazoo_apps@###KAZOO###-<0.15279.184>-0c2a6896 via channel <0.24227.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:328 (<0.15279.184>) created consumer amq.ctag-6-PF4gsv4OEmOJpdqTCprA via channel <0.24227.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:872 (<0.15279.184>) queue started: kazoo_apps@###KAZOO###-<0.15279.184>-0c2a6896

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:1021 (<0.15279.184>) creating new binding: 'call'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:328 (<0.15283.184>) created consumer amq.ctag-tazgu8rfAR3Rfi952yraZQ via channel <0.24239.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:872 (<0.15283.184>) queue started: kazoo_apps@###KAZOO###-<0.15283.184>-b29e89a2

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:1021 (<0.15283.184>) creating new binding: 'call'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:321 (<0.15279.184>) bound kazoo_apps@###KAZOO###-<0.15279.184>-0c2a6896 to callevt exchange (routing key call.publisher_usurp.d7062594-6c35-45ae-a74f-1117c8c269aa) via channel <0.24227.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:321 (<0.15283.184>) bound kazoo_apps@###KAZOO###-<0.15283.184>-b29e89a2 to callevt exchange (routing key call.usurp_control.d7062594-6c35-45ae-a74f-1117c8c269aa) via channel <0.24239.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:1021 (<0.15283.184>) creating new binding: 'dialplan'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:321 (<0.15283.184>) bound kazoo_apps@###KAZOO###-<0.15283.184>-b29e89a2 to callctl exchange (routing key kazoo_apps@###KAZOO###-<0.15283.184>-b29e89a2) via channel <0.24239.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:1021 (<0.15283.184>) creating new binding: 'self'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:321 (<0.15283.184>) bound kazoo_apps@###KAZOO###-<0.15283.184>-b29e89a2 to targeted exchange (routing key kazoo_apps@###KAZOO###-<0.15283.184>-b29e89a2) via channel <0.24239.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_control:469 (<0.15283.184>) sending route_win to kazoo_apps@###KAZOO###-<0.927.0>-250796c1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.15283.184>) published to targeted(amqp://user:pa...@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.927.0>-250796c1) via <0.24239.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_control:477 (<0.15283.184>) sending control usurp for adef768b-3924-4d59-914a-48e84ea738d8

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:723 (<0.927.0>) response for msg id d7062594-6c35-45ae-a74f-1117c8c269aa took 60569 micro to return

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_route_req:219 (<0.15235.184>) callflow has received a route win, taking control of the call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.15283.184>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.usurp_control.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.24239.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:815 (<0.1105.0>) storing {kzs_cache,<<"account%2F10%2F64%2F9a107597e30ee5fcd1f743678ad1">>,<<"configs_number_manager">>} for 900s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:817 (<0.1105.0>) inserted {kzs_cache,<<"account%2F10%2F64%2F9a107597e30ee5fcd1f743678ad1">>,<<"configs_number_manager">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:819 (<0.1105.0>) inserted origin pointers for {kzs_cache,<<"account%2F10%2F64%2F9a107597e30ee5fcd1f743678ad1">>,<<"configs_number_manager">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:821 (<0.1105.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:815 (<0.1105.0>) storing {kzs_cache,<<"services">>,<<"10649a107597e30ee5fcd1f743678ad1">>} for 900s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:817 (<0.1105.0>) inserted {kzs_cache,<<"services">>,<<"10649a107597e30ee5fcd1f743678ad1">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:819 (<0.1105.0>) inserted origin pointers for {kzs_cache,<<"services">>,<<"10649a107597e30ee5fcd1f743678ad1">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:821 (<0.1105.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:815 (<0.1105.0>) storing {kzs_cache,<<"account%2F33%2F2c%2Fdb84b92ad1181a17a9ed90e7dfae">>,<<"configs_number_manager">>} for 900s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:817 (<0.1105.0>) inserted {kzs_cache,<<"account%2F33%2F2c%2Fdb84b92ad1181a17a9ed90e7dfae">>,<<"configs_number_manager">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:819 (<0.1105.0>) inserted origin pointers for {kzs_cache,<<"account%2F33%2F2c%2Fdb84b92ad1181a17a9ed90e7dfae">>,<<"configs_number_manager">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:821 (<0.1105.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|knm_converters:279 (<0.15235.184>) number '0451234567' is classified as unknown

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_route_win:100 (<0.15235.184>) classified number 0451234567 as unknown, testing for call restrictions

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_route_win:37 (<0.15235.184>) setting initial information about the call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_attributes:413 (<0.15235.184>) initiating endpoint is owned by b27257e420981374d1f81671cfa39a0b

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_route_win:239 (<0.15235.184>) setting language 'en-us' for this call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_attributes:118 (<0.15235.184>) endpoint configured with external caller id number +3589987654321

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_attributes:142 (<0.15235.184>) replacing empty caller id name with SIP caller id name 0912345678

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_attributes:198 (<0.15235.184>) determined external caller id is <0912345678> +3589987654321

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_route_win:264 (<0.15235.184>) bootstrapping with caller id type external: "0912345678" +3589987654321

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.15235.184>) published to callctl(amqp://user:pa...@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.15283.184>-b29e89a2) via <0.1217.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_route_win:334 (<0.15235.184>) call has been setup, beginning to process the call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|gen_listener:364 (<0.15298.184>) starting new gen_listener proc : cf_exe

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_amqp_assignments|kz_amqp_assignments:475 (<0.139.0>) assigned existing channel <0.24331.181> on amqp://user:pa...@127.0.0.1:5672 to new consumer <0.15298.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_control:888 (<0.15283.184>) recv and executing set now!

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_amqp_assignments|kz_amqp_assignments:886 (<0.139.0>) registered handlers for channel <0.24331.181> to <0.15298.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_control:1037 (<0.15283.184>) executing call command 'set' 9c7a5d570b5cc5c10b92cdd2b6add0a0

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_exe:760 (<0.15298.184>) executing callflow ef3dc6fc6829f868dabb2094057ad412

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_exe:761 (<0.15298.184>) account id 10649a107597e30ee5fcd1f743678ad1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_exe:762 (<0.15298.184>) request 04512...@nodomain.com

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_exe:763 (<0.15298.184>) to 04512...@nodomain.com

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_exe:764 (<0.15298.184>) from 1000@demo1.###DOMAIN###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_exe:765 (<0.15298.184>) CID 0912345678 +3589987654321

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_exe:768 (<0.15298.184>) inception +3589987654321@###GATEWAY1###: using attributes for an external call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_exe:770 (<0.15298.184>) authorizing id c7977a34493ff042b898cf74e32f2d94

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:1131 (<0.15298.184>) channel started, let's connect

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_route_win:291 (<0.15235.184>) looking up endpoint for c7977a34493ff042b898cf74e32f2d94

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_route_win:294 (<0.15235.184>) trying to send metaflow for a-leg endpoint c7977a34493ff042b898cf74e32f2d94

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.15297.184>) Supervisor {<0.15297.184>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 127.0.0.1:50135 -> 127.0.0.1:5672">>,2202}) at pid <0.15286.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_router_call:212 (<0.15225.184>) xml fetch dialplan adef768b-3924-4d59-914a-48e84ea738d8 finished with success

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.15297.184>) Supervisor {<0.15297.184>,amqp_channel_sup} started amqp_channel:start_link(network, <0.145.0>, 2202, <0.15286.184>, {<<"client 127.0.0.1:50135 -> 127.0.0.1:5672">>,2202}) at pid <0.15266.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.15297.184>) Supervisor {<0.15297.184>,amqp_channel_sup} started rabbit_writer:start_link(#Port<0.3742>, 2202, 131072, rabbit_framing_amqp_0_9_1, <0.15266.184>, {<<"client 127.0.0.1:50135 -> 127.0.0.1:5672">>,2202}) at pid <0.15299.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_amqp_assignments|kz_amqp_assignments:600 (<0.139.0>) added new channel <0.15266.184> on amqp://user:pa...@127.0.0.1:5672 to available pool

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:302 (<0.15298.184>) declared queue kazoo_apps@###KAZOO###-<0.15298.184>-fafed5be via channel <0.24331.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:328 (<0.15298.184>) created consumer amq.ctag-ws1Vx6RoxoHgw71fdb4Z2w via channel <0.24331.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:872 (<0.15298.184>) queue started: kazoo_apps@###KAZOO###-<0.15298.184>-fafed5be

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:1021 (<0.15298.184>) creating new binding: 'call'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:321 (<0.15298.184>) bound kazoo_apps@###KAZOO###-<0.15298.184>-fafed5be to callevt exchange (routing key call.*.d7062594-6c35-45ae-a74f-1117c8c269aa) via channel <0.24331.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:1021 (<0.15298.184>) creating new binding: 'self'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:321 (<0.15298.184>) bound kazoo_apps@###KAZOO###-<0.15298.184>-fafed5be to targeted exchange (routing key kazoo_apps@###KAZOO###-<0.15298.184>-fafed5be) via channel <0.24331.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_exe:489 (<0.15298.184>) ready to recv events, launching the callflow

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|cf_exe:672 (<0.15298.184>) moving to action 'cf_offnet'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.15301.184>) published to callctl(amqp://user:pa...@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.15283.184>-b29e89a2) via <0.24331.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_attributes:118 (<0.15301.184>) endpoint configured with emergency caller id number +3589987654321

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_attributes:142 (<0.15301.184>) replacing empty caller id name with SIP caller id name 0912345678

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_attributes:192 (<0.15301.184>) determined emergency caller id is <0912345678> +3589987654321

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_attributes:118 (<0.15301.184>) endpoint configured with external caller id number +3589987654321

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_attributes:142 (<0.15301.184>) replacing empty caller id name with SIP caller id name 0912345678

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_attributes:198 (<0.15301.184>) determined external caller id is <0912345678> +3589987654321

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:815 (<0.1105.0>) storing {kzs_cache,<<"account%2F10%2F64%2F9a107597e30ee5fcd1f743678ad1">>,<<"configs_callflow">>} for 900s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:817 (<0.1105.0>) inserted {kzs_cache,<<"account%2F10%2F64%2F9a107597e30ee5fcd1f743678ad1">>,<<"configs_callflow">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:819 (<0.1105.0>) inserted origin pointers for {kzs_cache,<<"account%2F10%2F64%2F9a107597e30ee5fcd1f743678ad1">>,<<"configs_callflow">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:821 (<0.1105.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.15301.184>) published to resource(amqp://user:pa...@127.0.0.1:5672) exchange (routing key offnet.resource.req) via <0.24331.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|stepswitch_outbound:46 (<0.15303.184>) received outbound audio resource request for 0451234567: {[{<<"Presence-ID">>,<<"1000@demo1.###DOMAIN###">>},{<<"Outbound-Caller-ID-Number">>,<<"+3589987654321">>},{<<"Outbound-Caller-ID-Name">>,<<"0912345678">>},{<<"Inception">>,<<"+3589987654321@###GATEWAY1###">>},{<<"Ignore-Early-Media">>,<<"false">>},{<<"From-URI-Realm">>,<<"demo1.###DOMAIN###">>},{<<"Format-From-URI">>,false},{<<"Fax-T38-Enabled">>,false},{<<"Emergency-Caller-ID-Number">>,<<"+3589987654321">>},{<<"Emergency-Caller-ID-Name">>,<<"0912345678">>},{<<"Custom-Channel-Vars">>,{[{<<"Authorizing-ID">>,<<"c7977a34493ff042b898cf74e32f2d94">>},{<<"Owner-ID">>,<<"b27257e420981374d1f81671cfa39a0b">>}]}},{<<"Control-Queue">>,<<"kazoo_apps@###KAZOO###-<0.15283.184>-b29e89a2">>},{<<"Call-ID">>,<<"d7062594-6c35-45ae-a74f-1117c8c269aa">>},{<<"Bypass-E164">>,false},{<<"B-Leg-Events">>,[<<"DTMF">>]},{<<"Account-Realm">>,<<"demo1.###DOMAIN###">>},{<<"Account-ID">>,<<"10649a107597e30ee5fcd1f743678ad1">>},{<<"To-DID">>,<<"0451234567">>},{<<"Resource-Type">>,<<"audio">>},{<<"Application-Name">>,<<"bridge">>},{<<"Server-ID">>,<<"kazoo_apps@###KAZOO###-<0.15298.184>-fafed5be">>},{<<"Node">>,<<"kazoo_apps@###KAZOO###">>},{<<"Msg-ID">>,<<"6c7e17961060">>},{<<"Event-Name">>,<<"offnet_req">>},{<<"Event-Category">>,<<"resource">>},{<<"App-Version">>,<<"4.0.0">>},{<<"App-Name">>,<<"callflow">>}]}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|knm_phone_number:139 (<0.15303.184>) failed to open 0451234567 in undefined: invalid_db_name

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|knm_number:793 (<0.15303.184>) no port for 0451234567: {error,invalid_db_name}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|stepswitch_resources:242 (<0.15303.184>) attempting to find global resources

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|stepswitch_resources:400 (<0.15303.184>) no flags provided, filtering resources that require flags

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|stepswitch_resources:538 (<0.15303.184>) resource XXX-carrier matches number '0451234567' with regex match '0451234567'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|stepswitch_resources:476 (<0.15303.184>) building resource XXX-carrier endpoints

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|stepswitch_resources:1139 (<0.15303.184>) created gateway route sip:0451234567@###GATEWAY2###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|stepswitch_resources:1139 (<0.15303.184>) created gateway route sip:0451234567@###GATEWAY1###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|gen_listener:364 (<0.15306.184>) starting new gen_listener proc : stepswitch_bridge

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_amqp_assignments|kz_amqp_assignments:475 (<0.139.0>) assigned existing channel <0.24333.181> on amqp://user:pa...@127.0.0.1:5672 to new consumer <0.15306.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_amqp_assignments|kz_amqp_assignments:886 (<0.139.0>) registered handlers for channel <0.24333.181> to <0.15306.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:1131 (<0.15306.184>) channel started, let's connect

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.2228.0>) Supervisor stepswitch_request_sup started stepswitch_bridge:start_link([{[{<<"Route">>,<<"sip:0451234567@###GATEWAY2###">>},{<<"Callee-ID-Name">>,<<"0451234567">>},{<<"...">>,...},...]},...], {[{<<"Presence-ID">>,<<"1000@demo1.###DOMAIN###">>},{<<"Outbound-Caller-ID-Number">>,<<"+35898765432...">>},...]}) at pid <0.15306.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.15309.184>) Supervisor {<0.15309.184>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 127.0.0.1:50135 -> 127.0.0.1:5672">>,2203}) at pid <0.15310.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.15309.184>) Supervisor {<0.15309.184>,amqp_channel_sup} started amqp_channel:start_link(network, <0.145.0>, 2203, <0.15310.184>, {<<"client 127.0.0.1:50135 -> 127.0.0.1:5672">>,2203}) at pid <0.15311.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.15309.184>) Supervisor {<0.15309.184>,amqp_channel_sup} started rabbit_writer:start_link(#Port<0.3742>, 2203, 131072, rabbit_framing_amqp_0_9_1, <0.15311.184>, {<<"client 127.0.0.1:50135 -> 127.0.0.1:5672">>,2203}) at pid <0.15314.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |kz_amqp_assignments|kz_amqp_assignments:600 (<0.139.0>) added new channel <0.15311.184> on amqp://user:pa...@127.0.0.1:5672 to available pool

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:302 (<0.15306.184>) declared queue kazoo_apps@###KAZOO###-<0.15306.184>-d91e1009 via channel <0.24333.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:328 (<0.15306.184>) created consumer amq.ctag-RsI17ktnsDXQ1zxFINS6Kw via channel <0.24333.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:872 (<0.15306.184>) queue started: kazoo_apps@###KAZOO###-<0.15306.184>-d91e1009

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:1021 (<0.15306.184>) creating new binding: 'call'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:321 (<0.15306.184>) bound kazoo_apps@###KAZOO###-<0.15306.184>-d91e1009 to callevt exchange (routing key call.CHANNEL_DESTROY.d7062594-6c35-45ae-a74f-1117c8c269aa) via channel <0.24333.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:321 (<0.15306.184>) bound kazoo_apps@###KAZOO###-<0.15306.184>-d91e1009 to callevt exchange (routing key call.CHANNEL_REPLACED.d7062594-6c35-45ae-a74f-1117c8c269aa) via channel <0.24333.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:321 (<0.15306.184>) bound kazoo_apps@###KAZOO###-<0.15306.184>-d91e1009 to callevt exchange (routing key call.CHANNEL_TRANSFEROR.d7062594-6c35-45ae-a74f-1117c8c269aa) via channel <0.24333.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:321 (<0.15306.184>) bound kazoo_apps@###KAZOO###-<0.15306.184>-d91e1009 to callevt exchange (routing key call.CHANNEL_EXECUTE_COMPLETE.d7062594-6c35-45ae-a74f-1117c8c269aa) via channel <0.24333.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:321 (<0.15306.184>) bound kazoo_apps@###KAZOO###-<0.15306.184>-d91e1009 to callevt exchange (routing key call.CHANNEL_BRIDGE.d7062594-6c35-45ae-a74f-1117c8c269aa) via channel <0.24333.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|gen_listener:1021 (<0.15306.184>) creating new binding: 'self'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:321 (<0.15306.184>) bound kazoo_apps@###KAZOO###-<0.15306.184>-d91e1009 to targeted exchange (routing key kazoo_apps@###KAZOO###-<0.15306.184>-d91e1009) via channel <0.24333.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|stepswitch_bridge:338 (<0.15306.184>) set outbound caller id to +3589987654321 '0912345678'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.15306.184>) published to callctl(amqp://user:pa...@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.15283.184>-b29e89a2) via <0.24333.181>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|stepswitch_bridge:286 (<0.15306.184>) sent bridge command to kazoo_apps@###KAZOO###-<0.15283.184>-b29e89a2

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|kz_amqp_channel:159 (<0.1686.0>) published to targeted(amqp://user:pa...@127.0.0.1:5672) exchange (routing key statistics) via <0.1725.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_control:888 (<0.15283.184>) recv and executing set now!

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_control:1037 (<0.15283.184>) executing call command 'set' f843c3c46f68309af8c20e97143256c4

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_control:947 (<0.15283.184>) inserting at the tail of the control queue call command bridge

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_control:1037 (<0.15283.184>) executing call command 'bridge' c49a1b8151cfc5f9601add2d604b95f6

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_bridge:97 (<0.15283.184>) bridge is to loopback channel, starting local ringing

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:713 (<0.15279.184>) publishing call event channel_execute 'ring()'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.927.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1015.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.927.0>) published message 1475778115606019 for <0.15279.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:710 (<0.15279.184>) publishing call event channel_execute_complete 'ring()' result: _none_

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.927.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE_COMPLETE.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1015.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.927.0>) published message 1475778115606019 for <0.15279.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_util:133 (<0.15283.184>) execute on node frees...@10.0.0.1(d7062594-6c35-45ae-a74f-1117c8c269aa) ring_ready(): ok

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:116 (<0.15283.184>) sent msg to d7062594-6c35-45ae-a74f-1117c8c269aa to bind for b leg events [<<"DTMF">>]

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_bridge:49 (<0.15283.184>) creating bridge dialplan

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:283 (<0.15279.184>) will start event listener for b-leg if encountered

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_util:596 (<0.15283.184>) building bridge endpoint: [<<"route">>,undefined,undefined,<<"0451234567">>,<<"sip:0451234567@###GATEWAY2###">>,undefined,undefined]

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_util:596 (<0.15283.184>) building bridge endpoint: [<<"route">>,undefined,undefined,<<"0451234567">>,<<"sip:0451234567@###GATEWAY1###">>,undefined,undefined]

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_util:90 (<0.15283.184>) building xferext on node frees...@10.0.0.1: kz_multiset ^^;ignore_display_updates=true;ecallmgr_Account-ID=10649a107597e30ee5fcd1f743678ad1;ecallmgr_Reseller-ID=332cdb84b92ad1181a17a9ed90e7dfae;ecallmgr_Owner-ID=b27257e420981374d1f81671cfa39a0b;ecallmgr_Authorizing-ID=c7977a34493ff042b898cf74e32f2d94

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_util:90 (<0.15283.184>) building xferext on node frees...@10.0.0.1: set continue_on_fail=true

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_util:90 (<0.15283.184>) building xferext on node frees...@10.0.0.1: export sip_redirect_context=context_2

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_util:90 (<0.15283.184>) building xferext on node frees...@10.0.0.1: set hangup_after_bridge=true

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_util:90 (<0.15283.184>) building xferext on node frees...@10.0.0.1: export ecallmgr_Inception=${ecallmgr_Inception}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_util:90 (<0.15283.184>) building xferext on node frees...@10.0.0.1: export ecallmgr_Call-Interaction-ID=${ecallmgr_Call-Interaction-ID}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_util:90 (<0.15283.184>) building xferext on node frees...@10.0.0.1: bridge {origination_caller_id_number='+3589987654321',origination_caller_id_name='0912345678',ignore_early_media='false',ignore_display_updates='true',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Reseller-ID='332cdb84b92ad1181a17a9ed90e7dfae',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',effective_caller_id_number='+3589987654321',effective_caller_id_name='0912345678',local_var_clobber='true'}[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/0451234567@###GATEWAY2###|[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/0451234567@###GATEWAY1###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_util:90 (<0.15283.184>) building xferext on node frees...@10.0.0.1: event Event-Name=CUSTOM,Event-Subclass=kazoo::masquerade,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=bridge

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_util:90 (<0.15283.184>) building xferext on node frees...@10.0.0.1: park

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:713 (<0.15279.184>) publishing call event channel_execute 'set(continue_on_fail=true)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.927.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1015.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.927.0>) published message 1475778115806008 for <0.15279.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_control:735 (<0.15176.184>) added cleg 83957722-64ec-46af-940e-9a225a218a04 to call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:710 (<0.15279.184>) publishing call event channel_execute_complete 'set(sip_redirect_context=context_2)' result: _none_

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:706 (<0.15323.184>) publishing call event leg_created

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |83957722-64ec-46af-940e-9a225a218a04|ecallmgr_call_events:706 (<0.15319.184>) publishing call event channel_create

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |83957722-64ec-46af-940e-9a225a218a04|kz_amqp_channel:159 (<0.919.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_CREATE.83957722-64ec-46af-940e-9a225a218a04) via <0.1003.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |83957722-64ec-46af-940e-9a225a218a04|kz_amqp_worker:624 (<0.919.0>) published message 1475778115806008 for <0.15319.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.927.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE_COMPLETE.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1015.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.927.0>) published message 1475778115806008 for <0.15279.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.LEG_CREATED.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115806008 for <0.15323.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |83957722-64ec-46af-940e-9a225a218a04|ecallmgr_fs_authz:104 (<0.15319.184>) config ecallmgr.authz is disabled

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |83957722-64ec-46af-940e-9a225a218a04|ecallmgr_fs_authz:236 (<0.15319.184>) channel authorization succeeded, allowing call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:815 (<0.1692.0>) storing {authz_response,<<"83957722-64ec-46af-940e-9a225a218a04">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:817 (<0.1692.0>) inserted {authz_response,<<"83957722-64ec-46af-940e-9a225a218a04">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:819 (<0.1692.0>) inserted origin pointers for {authz_response,<<"83957722-64ec-46af-940e-9a225a218a04">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:821 (<0.1692.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:713 (<0.15279.184>) publishing call event channel_execute 'set(sip_redirect_context=context_2)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.937.0>) published message 1475778115806008 for <0.15279.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:713 (<0.15279.184>) publishing call event channel_execute 'set(hangup_after_bridge=true)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.937.0>) published message 1475778115806008 for <0.15279.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:713 (<0.15279.184>) publishing call event channel_execute 'set(ecallmgr_Inception=+3589987654321@###GATEWAY1###)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.937.0>) published message 1475778115806008 for <0.15279.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:713 (<0.15279.184>) publishing call event channel_execute 'set(ecallmgr_Call-Interaction-ID=63642997314-8a3a8214)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.937.0>) published message 1475778115806008 for <0.15279.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:710 (<0.15279.184>) publishing call event channel_execute_complete 'set(ecallmgr_Inception=+3589987654321@###GATEWAY1###)' result: _none_

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_control:695 (<0.15283.184>) added leg 83957722-64ec-46af-940e-9a225a218a04 to call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE_COMPLETE.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.937.0>) published message 1475778115806008 for <0.15279.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:706 (<0.15326.184>) publishing call event leg_created

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:713 (<0.15279.184>) publishing call event channel_execute 'bridge({origination_caller_id_number='+3589987654321',origination_caller_id_name='0912345678',ignore_early_media='false',ignore_display_updates='true',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Reseller-ID='332cdb84b92ad1181a17a9ed90e7dfae',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',effective_caller_id_number='+3589987654321',effective_caller_id_name='0912345678',local_var_clobber='true'}[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/0451234567@###GATEWAY2###|[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/0451234567@###GATEWAY1###)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |83957722-64ec-46af-940e-9a225a218a04|ecallmgr_fs_authz:34 (<0.15319.184>) channel is authorized

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.937.0>) published message 1475778115806008 for <0.15279.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:710 (<0.15279.184>) publishing call event channel_execute_complete 'set(ecallmgr_Call-Interaction-ID=63642997314-8a3a8214)' result: _none_

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE_COMPLETE.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.937.0>) published message 1475778115806008 for <0.15279.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |83957722-64ec-46af-940e-9a225a218a04|webhooks_channel_util:37 (<0.15330.184>) determined account id for CHANNEL_CREATE is 10649a107597e30ee5fcd1f743678ad1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |83957722-64ec-46af-940e-9a225a218a04|webhooks_channel_util:47 (<0.15330.184>) evt CHANNEL_CREATE for 10649a107597e30ee5fcd1f743678ad1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |83957722-64ec-46af-940e-9a225a218a04|webhooks_channel_util:49 (<0.15330.184>) no hooks to handle CHANNEL_CREATE for 10649a107597e30ee5fcd1f743678ad1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |2a9170c87de5ba0d|acdc_agent_manager:145 (<0.24506.144>) channel_create event

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |83957722-64ec-46af-940e-9a225a218a04|acdc_agent_handler:255 (<0.15336.184>) new channel in acct 10649a107597e30ee5fcd1f743678ad1: from 0451234567 to 0451234567(0451234567)

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |83957722-64ec-46af-940e-9a225a218a04|omnip_presence_amqp:189 (<0.15334.184>) received channel create, checking for presence subscribers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |83957722-64ec-46af-940e-9a225a218a04|omnip_presence_amqp:309 (<0.15334.184>) no presence subscriptions for 0451234567@###GATEWAY2###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |83957722-64ec-46af-940e-9a225a218a04|omnip_dialog_amqp:198 (<0.15337.184>) received channel create, checking for dialog subscribers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |83957722-64ec-46af-940e-9a225a218a04|omnip_dialog_amqp:370 (<0.15337.184>) no dialog subscriptions for 0451234567@###GATEWAY2###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.927.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.LEG_CREATED.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1015.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.927.0>) published message 1475778115806008 for <0.15326.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |f742c509d142281f|kz_amqp_channel:159 (<0.927.0>) published to nodes(amqp://user:pa...@127.0.0.1:5672) exchange (routing key ) via <0.1015.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |f742c509d142281f|kz_amqp_worker:624 (<0.927.0>) published message f742c509d142281f for <0.1207.0>

Oct 6 21:22:05 kazoo-server 2600hz[18190]: |0000000000|kz_amqp_channel:159 (<0.1686.0>) published to targeted(amqp://user:pa...@127.0.0.1:5672) exchange (routing key statistics) via <0.1725.0>

Oct 6 21:22:06 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_control:695 (<0.15283.184>) added leg e68da153-8a76-413d-9f5b-22423d75c999 to call

Oct 6 21:22:06 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:706 (<0.15405.184>) publishing call event leg_created

Oct 6 21:22:06 kazoo-server 2600hz[18190]: |e68da153-8a76-413d-9f5b-22423d75c999|ecallmgr_call_events:706 (<0.15406.184>) publishing call event channel_create

Oct 6 21:22:06 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_control:735 (<0.15176.184>) added cleg e68da153-8a76-413d-9f5b-22423d75c999 to call

Oct 6 21:22:06 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:706 (<0.15415.184>) publishing call event leg_created

Oct 6 21:22:06 kazoo-server 2600hz[18190]: |e68da153-8a76-413d-9f5b-22423d75c999|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_CREATE.e68da153-8a76-413d-9f5b-22423d75c999) via <0.1044.0>

Oct 6 21:22:06 kazoo-server 2600hz[18190]: |e68da153-8a76-413d-9f5b-22423d75c999|kz_amqp_worker:624 (<0.937.0>) published message 1475778126026052 for <0.15406.184>

Oct 6 21:22:06 kazoo-server 2600hz[18190]: |e68da153-8a76-413d-9f5b-22423d75c999|ecallmgr_fs_authz:104 (<0.15406.184>) config ecallmgr.authz is disabled

Oct 6 21:22:06 kazoo-server 2600hz[18190]: |e68da153-8a76-413d-9f5b-22423d75c999|ecallmgr_fs_authz:236 (<0.15406.184>) channel authorization succeeded, allowing call

Oct 6 21:22:06 kazoo-server 2600hz[18190]: |ecallmgr_interaction_cache|kz_cache:815 (<0.1695.0>) storing {channel,<<"83957722-64ec-46af-940e-9a225a218a04">>} for 3600s

Oct 6 21:22:06 kazoo-server 2600hz[18190]: |ecallmgr_interaction_cache|kz_cache:817 (<0.1695.0>) inserted {channel,<<"83957722-64ec-46af-940e-9a225a218a04">>}

Oct 6 21:22:06 kazoo-server 2600hz[18190]: |ecallmgr_interaction_cache|kz_cache:819 (<0.1695.0>) inserted origin pointers for {channel,<<"83957722-64ec-46af-940e-9a225a218a04">>}

Oct 6 21:22:06 kazoo-server 2600hz[18190]: |ecallmgr_interaction_cache|kz_cache:821 (<0.1695.0>) exec store callbacks

[Darren Schreiber]

The most important part of the logs are the FreeSWITCH logs in this case and you’ve parsed out half their data J

 

Can you just scrub the IPs if you’re concerned about privacy but keep the full packets please. If you scrub the IPs please keep the first two octets intact at least

--
You received this message because you are subscribed to the Google Groups "2600hz-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to 2600hz-users...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Mikko]

Hi Darren,

Here is the complete FS log with only the last 2 octets of the IP obscured.

2016-10-07 00:56:25.086054 [NOTICE] kazoo_node.c:302 log|5d0d1508-ca45-4956-9041-718f17d6351c|building xferext extension: bridge {origination_caller_id_number='+358987654321',origination_caller_id_name='0912345678',ignore_early_media='false',ignore_display_updates='true',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Reseller-ID='332cdb84b92ad1181a17a9ed90e7dfae',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',effective_caller_id_number='+358987654321',effective_caller_id_name='0912345678',local_var_clobber='true'}[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/04512...@212.213.XX.X2|[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/04512...@212.213.XX.X1

2016-10-07 00:56:25.086054 [NOTICE] kazoo_node.c:302 log|5d0d1508-ca45-4956-9041-718f17d6351c|building xferext extension: event Event-Name=CUSTOM,Event-Subclass=kazoo::masquerade,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=bridge

2016-10-07 00:56:25.086054 [NOTICE] kazoo_node.c:302 log|5d0d1508-ca45-4956-9041-718f17d6351c|building xferext extension: park

2016-10-07 00:56:25.086054 [NOTICE] kazoo_node.c:305 log|5d0d1508-ca45-4956-9041-718f17d6351c|transfered call to xferext extension

2016-10-07 00:56:25.086054 [DEBUG] mod_loopback.c:601 loopback/0451234567-b CHANNEL KILL

2016-10-07 00:56:25.086054 [DEBUG] switch_channel.c:3168 (loopback/0451234567-b) State Change CS_EXECUTE -> CS_ROUTING

2016-10-07 00:56:25.086054 [DEBUG] mod_loopback.c:601 loopback/0451234567-b CHANNEL KILL

2016-10-07 00:56:25.086054 [DEBUG] switch_core_state_machine.c:609 (loopback/0451234567-b) State EXECUTE going to sleep

2016-10-07 00:56:25.086054 [DEBUG] switch_core_state_machine.c:543 (loopback/0451234567-b) Running State Change CS_ROUTING

2016-10-07 00:56:25.086054 [DEBUG] switch_core_state_machine.c:602 (loopback/0451234567-b) State ROUTING

2016-10-07 00:56:25.086054 [DEBUG] mod_loopback.c:394 loopback/0451234567-b CHANNEL ROUTING

2016-10-07 00:56:25.086054 [DEBUG] switch_core_state_machine.c:236 loopback/0451234567-b Standard ROUTING

2016-10-07 00:56:25.086054 [DEBUG] switch_core_state_machine.c:256 (loopback/0451234567-b) State Change CS_ROUTING -> CS_EXECUTE

2016-10-07 00:56:25.086054 [DEBUG] mod_loopback.c:601 loopback/0451234567-b CHANNEL KILL

2016-10-07 00:56:25.086054 [DEBUG] switch_core_state_machine.c:602 (loopback/0451234567-b) State ROUTING going to sleep

2016-10-07 00:56:25.086054 [DEBUG] switch_core_state_machine.c:543 (loopback/0451234567-b) Running State Change CS_EXECUTE

2016-10-07 00:56:25.086054 [DEBUG] switch_core_state_machine.c:609 (loopback/0451234567-b) State EXECUTE

2016-10-07 00:56:25.086054 [DEBUG] mod_loopback.c:436 loopback/0451234567-b CHANNEL EXECUTE

2016-10-07 00:56:25.086054 [DEBUG] switch_core_state_machine.c:328 loopback/0451234567-b Standard EXECUTE

EXECUTE loopback/0451234567-b kz_multiset(^^;ignore_display_updates=true;ecallmgr_Account-ID=10649a107597e30ee5fcd1f743678ad1;ecallmgr_Reseller-ID=332cdb84b92ad1181a17a9ed90e7dfae;ecallmgr_Owner-ID=b27257e420981374d1f81671cfa39a0b;ecallmgr_Authorizing-ID=c7977a34493ff042b898cf74e32f2d94)

2016-10-07 00:56:25.086054 [DEBUG] kazoo_dptools.c:81 loopback/0451234567-b SET [ignore_display_updates]=[true]

2016-10-07 00:56:25.086054 [DEBUG] kazoo_dptools.c:81 loopback/0451234567-b SET [ecallmgr_Account-ID]=[10649a107597e30ee5fcd1f743678ad1]

2016-10-07 00:56:25.086054 [DEBUG] kazoo_dptools.c:81 loopback/0451234567-b SET [ecallmgr_Reseller-ID]=[332cdb84b92ad1181a17a9ed90e7dfae]

2016-10-07 00:56:25.086054 [DEBUG] kazoo_dptools.c:81 loopback/0451234567-b SET [ecallmgr_Owner-ID]=[b27257e420981374d1f81671cfa39a0b]

2016-10-07 00:56:25.086054 [DEBUG] kazoo_dptools.c:81 loopback/0451234567-b SET [ecallmgr_Authorizing-ID]=[c7977a34493ff042b898cf74e32f2d94]

EXECUTE loopback/0451234567-b set(continue_on_fail=true)

2016-10-07 00:56:25.086054 [DEBUG] mod_dptools.c:1519 SET loopback/0451234567-b [continue_on_fail]=[true]

EXECUTE loopback/0451234567-b export(sip_redirect_context=context_2)

2016-10-07 00:56:25.086054 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [sip_redirect_context]=[context_2]

EXECUTE loopback/0451234567-b set(hangup_after_bridge=true)

2016-10-07 00:56:25.086054 [DEBUG] mod_dptools.c:1519 SET loopback/0451234567-b [hangup_after_bridge]=[true]

EXECUTE loopback/0451234567-b export(ecallmgr_Inception=+358987654321@212.213.XX.X1)

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Inception]=[+358987654321@212.213.XX.X1]

EXECUTE loopback/0451234567-b export(ecallmgr_Call-Interaction-ID=63643010183-9f536e04)

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Call-Interaction-ID]=[63643010183-9f536e04]

EXECUTE loopback/0451234567-b bridge({origination_caller_id_number='+358987654321',origination_caller_id_name='0912345678',ignore_early_media='false',ignore_display_updates='true',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Reseller-ID='332cdb84b92ad1181a17a9ed90e7dfae',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',effective_caller_id_number='+358987654321',effective_caller_id_name='0912345678',local_var_clobber='true'}[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/04512...@212.213.XX.X2|[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/04512...@212.213.XX.X1)

2016-10-07 00:56:25.106049 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 5449

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Bridge-ID]=[2d697a833ad2106e...@src.company.fi] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[kazoo...@kazoo.domain.com] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [sip_redirect_context]=[context_2] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Inception]=[+358987654321@212.213.XX.X1] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Call-Interaction-ID]=[63643010183-9f536e04] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Bridge-ID]=[2d697a833ad2106e...@src.company.fi] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[kazoo...@kazoo.domain.com] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [sip_redirect_context]=[context_2] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Inception]=[+358987654321@212.213.XX.X1] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Call-Interaction-ID]=[63643010183-9f536e04] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_ivr_originate.c:2136 Parsing global variables

2016-10-07 00:56:25.106049 [DEBUG] switch_ivr_originate.c:2589 Parsing session specific variables

2016-10-07 00:56:25.106049 [NOTICE] switch_channel.c:1104 New Channel sofia/sipinterface_1/04512...@212.213.XX.X2 [ab3c5ea7-e971-479a-ac42-d8ec2baedd83]

2016-10-07 00:56:25.106049 [DEBUG] mod_sofia.c:4753 (sofia/sipinterface_1/04512...@212.213.XX.X2) State Change CS_NEW -> CS_INIT

2016-10-07 00:56:25.106049 [DEBUG] switch_ivr_originate.c:2892 sofia/sipinterface_1/04512...@212.213.XX.X2 Setting leg progress timeout to 10

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:543 (sofia/sipinterface_1/04512...@212.213.XX.X2) Running State Change CS_INIT

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:586 (sofia/sipinterface_1/04512...@212.213.XX.X2) State INIT

2016-10-07 00:56:25.106049 [DEBUG] mod_sofia.c:90 sofia/sipinterface_1/04512...@212.213.XX.X2 SOFIA INIT

2016-10-07 00:56:25.106049 [DEBUG] sofia_glue.c:1276 sofia/sipinterface_1/04512...@212.213.XX.X2 sending invite version: 1.6.10 -17-726448d 64bit

Local SDP:

v=0

o=FreeSWITCH 1475778277 1475778278 IN IP4 188.117.XX.XX

s=FreeSWITCH

c=IN IP4 188.117.XX.XX

t=0 0

m=audio 12708 RTP/AVP 8 0 101 13

a=rtpmap:8 PCMA/8000

a=rtpmap:0 PCMU/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=rtpmap:13 CN/8000

a=ptime:20

a=sendrecv

send 1173 bytes to udp/[212.213.XX.X2]:5060 at 00:56:25.107867:

------------------------------------------------------------------------

INVITE sip:04512...@212.213.XX.X2 SIP/2.0

Via: SIP/2.0/UDP 172.17.0.7:11000;rport;branch=z9hG4bKQF1S7FBtB51Zc

Max-Forwards: 70

From: "0912345678" <sip:+35898...@172.17.0.7>;tag=XtvmpXvK3gmjB

To: <sip:04512...@212.213.XX.X2>

Call-ID: ab3c5ea7-e971-479a-ac42-d8ec2baedd83

CSeq: 97559428 INVITE

Contact: <sip:mod_...@172.17.0.7:11000>

User-Agent: 2600hz

Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE

Supported: path, replaces

Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer

Content-Type: application/sdp

Content-Disposition: session

Content-Length: 270

X-FS-Support: update_display,send_info

Remote-Party-ID: "0912345678" <sip:+35898...@172.17.0.7>;party=calling;screen=yes;privacy=off

v=0

o=FreeSWITCH 1475778277 1475778278 IN IP4 188.117.XX.XX

s=FreeSWITCH

c=IN IP4 188.117.XX.XX

t=0 0

m=audio 12708 RTP/AVP 8 0 101 13

a=rtpmap:8 PCMA/8000

a=rtpmap:0 PCMU/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=rtpmap:13 CN/8000

a=ptime:20

------------------------------------------------------------------------

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/04512...@212.213.XX.X2 Standard INIT

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/04512...@212.213.XX.X2) State Change CS_INIT -> CS_ROUTING

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:586 (sofia/sipinterface_1/04512...@212.213.XX.X2) State INIT going to sleep

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:543 (sofia/sipinterface_1/04512...@212.213.XX.X2) Running State Change CS_ROUTING

2016-10-07 00:56:25.106049 [DEBUG] sofia.c:6962 Channel sofia/sipinterface_1/04512...@212.213.XX.X2 entering state [calling][0]

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:602 (sofia/sipinterface_1/04512...@212.213.XX.X2) State ROUTING

2016-10-07 00:56:25.106049 [DEBUG] mod_sofia.c:143 sofia/sipinterface_1/04512...@212.213.XX.X2 SOFIA ROUTING

2016-10-07 00:56:25.106049 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_1/04512...@212.213.XX.X2) State Change CS_ROUTING -> CS_CONSUME_MEDIA

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:602 (sofia/sipinterface_1/04512...@212.213.XX.X2) State ROUTING going to sleep

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:543 (sofia/sipinterface_1/04512...@212.213.XX.X2) Running State Change CS_CONSUME_MEDIA

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:621 (sofia/sipinterface_1/04512...@212.213.XX.X2) State CONSUME_MEDIA

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:621 (sofia/sipinterface_1/04512...@212.213.XX.X2) State CONSUME_MEDIA going to sleep

recv 388 bytes from udp/[212.213.XX.X2]:5060 at 00:56:25.112800:

------------------------------------------------------------------------

SIP/2.0 100 trying -- your call is important to us

Via: SIP/2.0/UDP 172.17.0.7:11000;rport=11000;branch=z9hG4bKQF1S7FBtB51Zc;received=188.117.XX.XX

From: "0912345678" <sip:+35898...@172.17.0.7>;tag=XtvmpXvK3gmjB

To: <sip:04512...@212.213.XX.X2>

Call-ID: ab3c5ea7-e971-479a-ac42-d8ec2baedd83

CSeq: 97559428 INVITE

Server: kamailio (4.1.6 (i386/solaris))

Content-Length: 0

------------------------------------------------------------------------

2016-10-07 00:56:25.106049 [DEBUG] kazoo_node.c:1100 Sent erlang message to kazoo...@kazoo.domain.com <2.1471.187>

2016-10-07 00:56:25.106049 [INFO] kazoo_node.c:625 exec: kz_uuid_setvar_multi(ab3c5ea7-e971-479a-ac42-d8ec2baedd83 ^^;ecallmgr_Account-ID=10649a107597e30ee5fcd1f743678ad1;ecallmgr_Reseller-ID=332cdb84b92ad1181a17a9ed90e7dfae;ecallmgr_Global-Resource=true;ecallmgr_Channel-Authorized=true)

2016-10-07 00:56:25.126005 [DEBUG] kazoo_node.c:1100 Sent erlang message to kazoo...@kazoo.domain.com <2.1542.187>

2016-10-07 00:56:25.126005 [INFO] kazoo_node.c:625 exec: kz_uuid_setvar_multi(ab3c5ea7-e971-479a-ac42-d8ec2baedd83 ecallmgr_Call-Interaction-ID=63643010183-9f536e04)

2016-10-07 00:56:25.326040 [DEBUG] kazoo_node.c:1100 Sent erlang message to kazoo...@kazoo.domain.com <2.1471.187>

recv 1058 bytes from udp/[212.213.XX.X2]:5060 at 00:56:29.334245:

------------------------------------------------------------------------

SIP/2.0 183 Session Progress

Call-ID: ab3c5ea7-e971-479a-ac42-d8ec2baedd83

CSeq: 97559428 INVITE

From: "0912345678" <sip:+35898...@172.17.0.7>;tag=XtvmpXvK3gmjB

To: <sip:04512...@212.213.XX.X2>;tag=sip+1+200e0005+73160c37

Via: SIP/2.0/UDP 172.17.0.7:11000;received=188.117.XX.XX;rport=11000;branch=z9hG4bKQF1S7FBtB51Zc

Server: CISCO-SBC/2.x

Record-Route: <sip:212.213.XX.X2;transport=tcp;r2=on;lr;ftag=XtvmpXvK3gmjB;vst=AAAAAAAAAAAAAAAAAAAAAwELAAQIHR8HAwAMCw--;did=0e6.9281>

Record-Route: <sip:212.213.XX.X2;r2=on;lr;ftag=XtvmpXvK3gmjB;vst=AAAAAAAAAAAAAAAAAAAAAwELAAQIHR8HAwAMCw--;did=0e6.9281>

Content-Length: 344

Contact: <sip:109.69.XX.X1:5060;transport=tcp>

Content-Type: application/sdp

v=0

o=- 128369331693981 128369331693981 IN IP4 109.69.XX.X2

s=-

c=IN IP4 109.69.XX.X2

t=0 0

m=audio 20208 RTP/AVP 8 101

a=rtpmap:8 PCMA/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

a=X-sqn:0

a=X-cap: 1 audio RTP/AVP 100

a=X-cpar: a=rtpmap:100 X-NSE/8000

a=X-cpar: a=fmtp:100 192-194,200-202

a=X-cap: 2 image udptl t38

------------------------------------------------------------------------

2016-10-07 00:56:29.326056 [DEBUG] sofia.c:6962 Channel sofia/sipinterface_1/04512...@212.213.XX.X2 entering state [proceeding][183]

2016-10-07 00:56:29.326056 [DEBUG] sofia.c:6972 Remote SDP:

v=0

o=- 128369331693981 128369331693981 IN IP4 109.69.XX.X2

s=-

c=IN IP4 109.69.XX.X2

t=0 0

m=audio 20208 RTP/AVP 8 101

a=rtpmap:8 PCMA/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

a=X-sqn:0

a=X-cap: 1 audio RTP/AVP 100

a=X-cpar: a=rtpmap:100 X-NSE/8000

a=X-cpar: a=fmtp:100 192-194,200-202

a=X-cap: 2 image udptl t38

2016-10-07 00:56:36.006019 [NOTICE] switch_ivr_originate.c:322 Hangup sofia/sipinterface_1/04512...@212.213.XX.X2 [CS_CONSUME_MEDIA] [PROGRESS_TIMEOUT]

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:543 (sofia/sipinterface_1/04512...@212.213.XX.X2) Running State Change CS_HANGUP

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:809 (sofia/sipinterface_1/04512...@212.213.XX.X2) Callstate Change DOWN -> HANGUP

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:811 (sofia/sipinterface_1/04512...@212.213.XX.X2) State HANGUP

2016-10-07 00:56:36.006019 [DEBUG] mod_sofia.c:438 Channel sofia/sipinterface_1/04512...@212.213.XX.X2 hanging up, cause: PROGRESS_TIMEOUT

2016-10-07 00:56:36.006019 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/sipinterface_1/04512...@212.213.XX.X2

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/04512...@212.213.XX.X2 Standard HANGUP, cause: PROGRESS_TIMEOUT

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:811 (sofia/sipinterface_1/04512...@212.213.XX.X2) State HANGUP going to sleep

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:578 (sofia/sipinterface_1/04512...@212.213.XX.X2) State Change CS_HANGUP -> CS_REPORTING

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:543 (sofia/sipinterface_1/04512...@212.213.XX.X2) Running State Change CS_REPORTING

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:897 (sofia/sipinterface_1/04512...@212.213.XX.X2) State REPORTING

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:174 sofia/sipinterface_1/04512...@212.213.XX.X2 Standard REPORTING, cause: PROGRESS_TIMEOUT

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:897 (sofia/sipinterface_1/04512...@212.213.XX.X2) State REPORTING going to sleep

send 376 bytes to udp/[212.213.XX.X2]:5060 at 00:56:36.026067:

------------------------------------------------------------------------

CANCEL sip:04512...@212.213.XX.X2 SIP/2.0

Via: SIP/2.0/UDP 172.17.0.7:11000;rport;branch=z9hG4bKQF1S7FBtB51Zc

Max-Forwards: 70

From: "0912345678" <sip:+35898...@172.17.0.7>;tag=XtvmpXvK3gmjB

To: <sip:04512...@212.213.XX.X2>

Call-ID: ab3c5ea7-e971-479a-ac42-d8ec2baedd83

CSeq: 97559428 CANCEL

Reason: SIP;cause=607;text="PROGRESS_TIMEOUT"

Content-Length: 0

------------------------------------------------------------------------

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:569 (sofia/sipinterface_1/04512...@212.213.XX.X2) State Change CS_REPORTING -> CS_DESTROY

2016-10-07 00:56:36.006019 [DEBUG] switch_core_session.c:1647 Session 70 (sofia/sipinterface_1/04512...@212.213.XX.X2) Locked, Waiting on external entities

recv 401 bytes from udp/[212.213.XX.X2]:5060 at 00:56:36.030904:

------------------------------------------------------------------------

SIP/2.0 200 canceling

Via: SIP/2.0/UDP 172.17.0.7:11000;rport=11000;branch=z9hG4bKQF1S7FBtB51Zc;received=188.117.XX.XX

From: "0912345678" <sip:+35898...@172.17.0.7>;tag=XtvmpXvK3gmjB

To: <sip:04512...@212.213.XX.X2>;tag=eed6322f0191e495094566a9c9fe2820-9d64

Call-ID: ab3c5ea7-e971-479a-ac42-d8ec2baedd83

CSeq: 97559428 CANCEL

Server: kamailio (4.1.6 (i386/solaris))

Content-Length: 0

------------------------------------------------------------------------

2016-10-07 00:56:36.026238 [DEBUG] switch_ivr_originate.c:3759 Originate Resulted in Error Cause: 607 [PROGRESS_TIMEOUT]

2016-10-07 00:56:36.026238 [DEBUG] switch_ivr_originate.c:2589 Parsing session specific variables

2016-10-07 00:56:36.026238 [NOTICE] switch_core_session.c:1665 Session 70 (sofia/sipinterface_1/04512...@212.213.XX.X2) Ended

2016-10-07 00:56:36.026238 [NOTICE] switch_core_session.c:1669 Close Channel sofia/sipinterface_1/04512...@212.213.XX.X2 [CS_DESTROY]

2016-10-07 00:56:36.026238 [DEBUG] switch_core_state_machine.c:700 (sofia/sipinterface_1/04512...@212.213.XX.X2) Running State Change CS_DESTROY

Oct 6 21:21:54 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.15198.184>) published to callctl(amqp://user:pass@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.15176.184>-6d559d63) via <0.24232.181>

Oct 6 21:21:54 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kapps_call_command:2471 (<0.15198.184>) waiting for bridge for 70000 ms

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_control:947 (<0.15176.184>) inserting at the tail of the control queue call command bridge

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_control:1037 (<0.15176.184>) executing call command 'bridge' ba19e0470bdd7e48821354914effda25

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_fs_bridge:49 (<0.15176.184>) creating bridge dialplan

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_config:185 (<0.15176.184>) looking up 'use_bypass_media_after_bridge' from sysconf

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_channel:159 (<0.937.0>) published to sysconf(amqp://user:pass@127.0.0.1:5672) exchange (routing key sysconf.get) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_worker:563 (<0.937.0>) published request with msg id a1f6a675640f220478097cf9c9aa3cb8 for <0.15176.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|sysconf_get:29 (<0.15206.184>) received sysconf get for ecallmgr:use_bypass_media_after_bridge from kazoo_apps@###KAZOO###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|sysconf_get:34 (<0.15206.184>) sending reply for ecallmgr.use_bypass_media_after_bridge(kazoo_apps@###KAZOO###): false

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_channel:159 (<0.15206.184>) published to targeted(amqp://user:pass@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.937.0>-f5433ed8) via <0.1103.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_worker:723 (<0.937.0>) response for msg id a1f6a675640f220478097cf9c9aa3cb8 took 7634 micro to return

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:815 (<0.1692.0>) storing {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:817 (<0.1692.0>) inserted {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:819 (<0.1692.0>) inserted origin pointers for {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:821 (<0.1692.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:596 (<0.15176.184>) building bridge endpoint: [<<"route">>,undefined,undefined,<<"+3589987654321">>,<<"loopback/0451234567">>,undefined,undefined]

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: set continue_on_fail=true

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export sip_redirect_context=context_2

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: set hangup_after_bridge=true

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export ecallmgr_Inception=${ecallmgr_Inception}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export ecallmgr_Call-Interaction-ID=${ecallmgr_Call-Interaction-ID}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: bridge {call_timeout=60,originate_timeout=60,outbound_redirect_fatal='false',ignore_early_media='true',local_var_clobber='true'}[presence_id='1000@demo1.###DOMAIN###',ignore_early_media='true',leg_timeout='60',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Call-Forward='true',ecallmgr_Authorizing-Type='device',loopback_bowout_on_execute='false',loopback_bowout='true',sdp_secure_savp_only='false',sip_invite_domain='###GATEWAY1###']loopback/0451234567

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: event Event-Name=CUSTOM,Event-Subclass=kazoo::masquerade,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=bridge

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: park

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(continue_on_fail=true)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(sip_redirect_context=context_2)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(hangup_after_bridge=true)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:710 (<0.15175.184>) publishing call event channel_execute_complete 'set(sip_redirect_context=context_2)' result: _none_

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE_COMPLETE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(ecallmgr_Inception=+3589987654321@###GATEWAY1###)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(ecallmgr_Call-Interaction-ID=63642997314-8a3a8214)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'bridge({call_timeout=60,originate_timeout=60,outbound_redirect_fatal='false',ignore_early_media='true',local_var_clobber='true'}[presence_id='1000@demo1.###DOMAIN###',ignore_early_media='true',leg_timeout='60',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Call-Forward='true',ecallmgr_Authorizing-Type='device',loopback_bowout_on_execute='false',loopback_bowout='true',sdp_secure_savp_only='false',sip_invite_domain='###GATEWAY1###']loopback/0451234567)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:710 (<0.15175.184>) publishing call event channel_execute_complete 'set(ecallmgr_Inception=+3589987654321@###GATEWAY1###)' result: _none_

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE_COMPLETE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:710 (<0.15175.184>) publishing call event channel_execute_complete 'set(ecallmgr_Call-Interaction-ID=63642997314-8a3a8214)' result: _none_

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE_COMPLETE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:706 (<0.15175.184>) publishing call event channel_progress_media

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.CHANNEL_PROGRESS_MEDIA.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|ecallmgr_call_events:706 (<0.15220.184>) publishing call event channel_create

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.CHANNEL_CREATE.d2f7fbbc-fdff-452b-b07c-c8dd7a53296a) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15220.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|ecallmgr_fs_authz:104 (<0.15220.184>) config ecallmgr.authz is disabled

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|ecallmgr_fs_authz:236 (<0.15220.184>) channel authorization succeeded, allowing call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:706 (<0.15221.184>) publishing call event channel_create

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.CHANNEL_CREATE.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15221.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_authz:104 (<0.15221.184>) config ecallmgr.authz is disabled

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_authz:236 (<0.15221.184>) channel authorization succeeded, allowing call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:815 (<0.1692.0>) storing {authz_response,<<"d2f7fbbc-fdff-452b-b07c-c8dd7a53296a">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:817 (<0.1692.0>) inserted {authz_response,<<"d2f7fbbc-fdff-452b-b07c-c8dd7a53296a">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:819 (<0.1692.0>) inserted origin pointers for {authz_response,<<"d2f7fbbc-fdff-452b-b07c-c8dd7a53296a">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:821 (<0.1692.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:815 (<0.1692.0>) storing {authz_response,<<"d7062594-6c35-45ae-a74f-1117c8c269aa">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:817 (<0.1692.0>) inserted {authz_response,<<"d7062594-6c35-45ae-a74f-1117c8c269aa">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:819 (<0.1692.0>) inserted origin pointers for {authz_response,<<"d7062594-6c35-45ae-a74f-1117c8c269aa">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:821 (<0.1692.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|webhooks_channel_util:37 (<0.15223.184>) determined account id for CHANNEL_CREATE is 10649a107597e30ee5fcd1f743678ad1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|webhooks_channel_util:37 (<0.15224.184>) determined account id for CHANNEL_CREATE is 10649a107597e30ee5fcd1f743678ad1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_authz:104 (<0.15228.184>) config ecallmgr.authz is disabled

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|omnip_presence_amqp:189 (<0.15232.184>) received channel create, checking for presence subscribers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|omnip_presence_amqp:189 (<0.15231.184>) received channel create, checking for presence subscribers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|omnip_dialog_amqp:198 (<0.15236.184>) received channel create, checking for dialog subscribers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|omnip_dialog_amqp:198 (<0.15233.184>) received channel create, checking for dialog subscribers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.937.0>) published to callmgr(amqp://user:pass@127.0.0.1:5672) exchange (routing key route.req.audio.demo1%2E###DOMAIN###.1000) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.927.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.LEG_CREATED.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1015.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.927.0>) published message 1475778115046007 for <0.15250.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|ecallmgr_fs_authz:34 (<0.15220.184>) channel is authorized

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.2310.0>) Supervisor ts_onnet_sup started ts_from_onnet:start_link({[{<<"Caller-ID-Number">>,<<"0912345678">>},{<<"Caller-ID-Name">>,<<"0912345678">>},{<<"Call-D...">>,...},...]}) at pid <0.15251.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |df071485f710dd99|kz_cache:815 (<0.1409.0>) storing {cf_patterns,<<"10649a107597e30ee5fcd1f743678ad1">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |df071485f710dd99|kz_cache:817 (<0.1409.0>) inserted {cf_patterns,<<"10649a107597e30ee5fcd1f743678ad1">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |df071485f710dd99|kz_cache:819 (<0.1409.0>) inserted origin pointers for {cf_patterns,<<"10649a107597e30ee5fcd1f743678ad1">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |df071485f710dd99|kz_cache:821 (<0.1409.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:815 (<0.1105.0>) storing {kzs_cache,<<"account%2F10%2F64%2F9a107597e30ee5fcd1f743678ad1">>,<<"ef3dc6fc6829f868dabb2094057ad412

...

[Darren Schreiber]

Looking at this log, I agree with you. The progress timeout was clearly received, and acknowledged, by FS. This looks broken to me.

 

You are on 1.6.10 -17-726448d 64bit - I would suggest trying scanning the FreeSWITCH JIRA to see if there are any recent bugs with progress timeouts. If there are not, I would try another version or master of FS first, and then file a bug on their wiki as I don’t have any explanation I can think of for why this would timeout despite having the progress. One small possibility is perhaps the loopback/ usage which is involved here is causing the progress to be tracked on a temporary loopback leg while the actual timer is on an alternate leg and since the call is not answered, the loopback doesn’t bow-out, thus, there’s the issue.

Oct 6 21:21:54 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.15198.184>) published to callctl(amqp://user:pa...@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.15176.184>-6d559d63) via <0.24232.181>

Oct 6 21:21:54 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kapps_call_command:2471 (<0.15198.184>) waiting for bridge for 70000 ms

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_control:947 (<0.15176.184>) inserting at the tail of the control queue call command bridge

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_control:1037 (<0.15176.184>) executing call command 'bridge' ba19e0470bdd7e48821354914effda25

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_fs_bridge:49 (<0.15176.184>) creating bridge dialplan

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_config:185 (<0.15176.184>) looking up 'use_bypass_media_after_bridge' from sysconf

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_channel:159 (<0.937.0>) published to sysconf(amqp://user:pa...@127.0.0.1:5672) exchange (routing key sysconf.get) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_worker:563 (<0.937.0>) published request with msg id a1f6a675640f220478097cf9c9aa3cb8 for <0.15176.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|sysconf_get:29 (<0.15206.184>) received sysconf get for ecallmgr:use_bypass_media_after_bridge from kazoo_apps@###KAZOO###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|sysconf_get:34 (<0.15206.184>) sending reply for ecallmgr.use_bypass_media_after_bridge(kazoo_apps@###KAZOO###): false

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_channel:159 (<0.15206.184>) published to targeted(amqp://user:pa...@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.937.0>-f5433ed8) via <0.1103.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_worker:723 (<0.937.0>) response for msg id a1f6a675640f220478097cf9c9aa3cb8 took 7634 micro to return

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:815 (<0.1692.0>) storing {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:817 (<0.1692.0>) inserted {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:819 (<0.1692.0>) inserted origin pointers for {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:821 (<0.1692.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:596 (<0.15176.184>) building bridge endpoint: [<<"route">>,undefined,undefined,<<"+3589987654321">>,<<"loopback/0451234567">>,undefined,undefined]

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: set continue_on_fail=true

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export sip_redirect_context=context_2

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: set hangup_after_bridge=true

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export ecallmgr_Inception=${ecallmgr_Inception}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export ecallmgr_Call-Interaction-ID=${ecallmgr_Call-Interaction-ID}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: bridge {call_timeout=60,originate_timeout=60,outbound_redirect_fatal='false',ignore_early_media='true',local_var_clobber='true'}[presence_id='1000@demo1.###DOMAIN###',ignore_early_media='true',leg_timeout='60',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Call-Forward='true',ecallmgr_Authorizing-Type='device',loopback_bowout_on_execute='false',loopback_bowout='true',sdp_secure_savp_only='false',sip_invite_domain='###GATEWAY1###']loopback/0451234567

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: event Event-Name=CUSTOM,Event-Subclass=kazoo::masquerade,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=bridge

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: park

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(continue_on_fail=true)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(sip_redirect_context=context_2)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(hangup_after_bridge=true)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:710 (<0.15175.184>) publishing call event channel_execute_complete 'set(sip_redirect_context=context_2)' result: _none_

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE_COMPLETE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(ecallmgr_Inception=+3589987654321@###GATEWAY1###)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(ecallmgr_Call-Interaction-ID=63642997314-8a3a8214)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'bridge({call_timeout=60,originate_timeout=60,outbound_redirect_fatal='false',ignore_early_media='true',local_var_clobber='true'}[presence_id='1000@demo1.###DOMAIN###',ignore_early_media='true',leg_timeout='60',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Call-Forward='true',ecallmgr_Authorizing-Type='device',loopback_bowout_on_execute='false',loopback_bowout='true',sdp_secure_savp_only='false',sip_invite_domain='###GATEWAY1###']loopback/0451234567)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:710 (<0.15175.184>) publishing call event channel_execute_complete 'set(ecallmgr_Inception=+3589987654321@###GATEWAY1###)' result: _none_

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE_COMPLETE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:710 (<0.15175.184>) publishing call event channel_execute_complete 'set(ecallmgr_Call-Interaction-ID=63642997314-8a3a8214)' result: _none_

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE_COMPLETE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:706 (<0.15175.184>) publishing call event channel_progress_media

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_PROGRESS_MEDIA.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|ecallmgr_call_events:706 (<0.15220.184>) publishing call event channel_create

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_CREATE.d2f7fbbc-fdff-452b-b07c-c8dd7a53296a) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15220.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|ecallmgr_fs_authz:104 (<0.15220.184>) config ecallmgr.authz is disabled

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|ecallmgr_fs_authz:236 (<0.15220.184>) channel authorization succeeded, allowing call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_call_events:706 (<0.15221.184>) publishing call event channel_create

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_CREATE.d7062594-6c35-45ae-a74f-1117c8c269aa) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15221.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_authz:104 (<0.15221.184>) config ecallmgr.authz is disabled

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_authz:236 (<0.15221.184>) channel authorization succeeded, allowing call

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:815 (<0.1692.0>) storing {authz_response,<<"d2f7fbbc-fdff-452b-b07c-c8dd7a53296a">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:817 (<0.1692.0>) inserted {authz_response,<<"d2f7fbbc-fdff-452b-b07c-c8dd7a53296a">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:819 (<0.1692.0>) inserted origin pointers for {authz_response,<<"d2f7fbbc-fdff-452b-b07c-c8dd7a53296a">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:821 (<0.1692.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:815 (<0.1692.0>) storing {authz_response,<<"d7062594-6c35-45ae-a74f-1117c8c269aa">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:817 (<0.1692.0>) inserted {authz_response,<<"d7062594-6c35-45ae-a74f-1117c8c269aa">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:819 (<0.1692.0>) inserted origin pointers for {authz_response,<<"d7062594-6c35-45ae-a74f-1117c8c269aa">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:821 (<0.1692.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|webhooks_channel_util:37 (<0.15223.184>) determined account id for CHANNEL_CREATE is 10649a107597e30ee5fcd1f743678ad1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|webhooks_channel_util:37 (<0.15224.184>) determined account id for CHANNEL_CREATE is 10649a107597e30ee5fcd1f743678ad1

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|ecallmgr_fs_authz:104 (<0.15228.184>) config ecallmgr.authz is disabled

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|omnip_presence_amqp:189 (<0.15232.184>) received channel create, checking for presence subscribers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|omnip_presence_amqp:189 (<0.15231.184>) received channel create, checking for presence subscribers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|omnip_dialog_amqp:198 (<0.15236.184>) received channel create, checking for dialog subscribers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|omnip_dialog_amqp:198 (<0.15233.184>) received channel create, checking for dialog subscribers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d7062594-6c35-45ae-a74f-1117c8c269aa|kz_amqp_channel:159 (<0.937.0>) published to callmgr(amqp://user:pa...@127.0.0.1:5672) exchange (routing key route.req.audio.demo1%2E###DOMAIN###.1000) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.927.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.LEG_CREATED.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1015.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.927.0>) published message 1475778115046007 for <0.15250.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |d2f7fbbc-fdff-452b-b07c-c8dd7a53296a|ecallmgr_fs_authz:34 (<0.15220.184>) channel is authorized

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |0000000000|Undefined:Undefined (<0.2310.0>) Supervisor ts_onnet_sup started ts_from_onnet:start_link({[{<<"Caller-ID-Number">>,<<"0912345678">>},{<<"Caller-ID-Name">>,<<"0912345678">>},{<<"Call-D...">>,...},...]}) at pid <0.15251.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |df071485f710dd99|kz_cache:815 (<0.1409.0>) storing {cf_patterns,<<"10649a107597e30ee5fcd1f743678ad1">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |df071485f710dd99|kz_cache:817 (<0.1409.0>) inserted {cf_patterns,<<"10649a107597e30ee5fcd1f743678ad1">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |df071485f710dd99|kz_cache:819 (<0.1409.0>) inserted origin pointers for {cf_patterns,<<"10649a107597e30ee5fcd1f743678ad1">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |df071485f710dd99|kz_cache:821 (<0.1409.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |3cbba5ca39559fa7|kz_cache:815 (<0.1105.0>) storing {kzs_cache,<<"account%2F10%2F64%2F9a107597e30ee5fcd1f743678ad1">>,<<"ef3dc6fc6829f868dabb2094057ad412

...

[Mikko]

Thanks for your help diagnosing the problem. It looks like the problem was Freeswitch, like you suggested.
I pulled an ”apt-get upgrade” and this fixed the problem.
The new version is FreeSWITCH version: 1.6.11-19-5e413fe~64bit.

It seems that FS had some major failure when parsing the SDP content.
After upgrading, the log looks completely different after receiving the 183 message. Now it produces 3 notice lines about Pre-Answer and at least 30 debug line about the SDP parameters and state changes.
This also resolved a few other issues we were having. Such as before if a mobile user that is receiving a call cancels the call, they were directed to the next gateway, instead of terminating the call attempt and going to then next call flow element.

This morning I did a search of JIRA with a few keywords and couldn’t find anything related to this, but it seems this bug was fixed in the latest repo release.
Maybe something freaky happened when I installed it initially. Even though we have 2 instances that were exhibiting the same problems, the other instance was made by cloning the first.
Anyway I’m stoked it works now. Thanks!

On Friday, October 7, 2016 at 12:00:16 PM UTC+3, Darren Schreiber wrote:

Looking at this log, I agree with you. The progress timeout was clearly received, and acknowledged, by FS. This looks broken to me.

 

You are on 1.6.10 -17-726448d 64bit - I would suggest trying scanning the FreeSWITCH JIRA to see if there are any recent bugs with progress timeouts. If there are not, I would try another version or master of FS first, and then file a bug on their wiki as I don’t have any explanation I can think of for why this would timeout despite having the progress. One small possibility is perhaps the loopback/ usage which is involved here is causing the progress to be tracked on a temporary loopback leg while the actual timer is on an alternate leg and since the call is not answered, the loopback doesn’t bow-out, thus, there’s the issue.

 

From: Mikko <mikko.ra...@gbc.fi>
Date: Thursday, October 6, 2016 at 5:21 PM
To: 2600hz-users <2600hz...@googlegroups.com>
Cc: Darren Schreiber <dschr...@2600hz.com>
Subject: Re: Outbound calls through offnet fail progress timeout

 

Hi Darren,

 

Here is the complete FS log with only the last 2 octets of the IP obscured.

 

 

2016-10-07 00:56:25.086054 [NOTICE] kazoo_node.c:302 log|5d0d1508-ca45-4956-9041-718f17d6351c|building xferext extension: bridge {origination_caller_id_number='+358987654321',origination_caller_id_name='0912345678',ignore_early_media='false',ignore_display_updates='true',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Reseller-ID='332cdb84b92ad1181a17a9ed90e7dfae',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',effective_caller_id_number='+358987654321',effective_caller_id_name='0912345678',local_var_clobber='true'}[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/0451234567@212.213.XX.X2|[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/0451234567@212.213.XX.X1

EXECUTE loopback/0451234567-b export(ecallmgr_Inception=+358987...@212.213.XX.X1)

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Inception]=[+358987...@212.213.XX.X1]

EXECUTE loopback/0451234567-b export(ecallmgr_Call-Interaction-ID=63643010183-9f536e04)

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Call-Interaction-ID]=[63643010183-9f536e04]

EXECUTE loopback/0451234567-b bridge({origination_caller_id_number='+358987654321',origination_caller_id_name='0912345678',ignore_early_media='false',ignore_display_updates='true',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Reseller-ID='332cdb84b92ad1181a17a9ed90e7dfae',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',effective_caller_id_number='+358987654321',effective_caller_id_name='0912345678',local_var_clobber='true'}[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/0451234567@212.213.XX.X2|[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/0451234567@212.213.XX.X1)

2016-10-07 00:56:25.106049 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 5449

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Bridge-ID]=[2d697a833ad2106e5b1369d3571d3b6b@src.company.fi] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[kazoo_a...@kazoo.domain.com] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [sip_redirect_context]=[context_2] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Inception]=[+358987...@212.213.XX.X1] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Call-Interaction-ID]=[63643010183-9f536e04] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Bridge-ID]=[2d697a833ad2106e5b1369d3571d3b6b@src.company.fi] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[kazoo_a...@kazoo.domain.com] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [sip_redirect_context]=[context_2] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Inception]=[+358987...@212.213.XX.X1] to event

From: "0912345678" <sip:+358...@172.17.0.7>;tag=XtvmpXvK3gmjB

To: <sip:04512...@212.213.XX.X2>

Call-ID: ab3c5ea7-e971-479a-ac42-d8ec2baedd83

CSeq: 97559428 INVITE

Contact: <sip:mod_...@172.17.0.7:11000>

User-Agent: 2600hz

Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE

Supported: path, replaces

Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer

Content-Type: application/sdp

Content-Disposition: session

Content-Length: 270

X-FS-Support: update_display,send_info

Remote-Party-ID: "0912345678" <sip:+358...@172.17.0.7>;party=calling;screen=yes;privacy=off

From: "0912345678" <sip:+358...@172.17.0.7>;tag=XtvmpXvK3gmjB

To: <sip:04512...@212.213.XX.X2>

Call-ID: ab3c5ea7-e971-479a-ac42-d8ec2baedd83

CSeq: 97559428 INVITE

Server: kamailio (4.1.6 (i386/solaris))

Content-Length: 0

------------------------------------------------------------------------

2016-10-07 00:56:25.106049 [DEBUG] kazoo_node.c:1100 Sent erlang message to kazoo...@kazoo.domain.com <2.1471.187>

2016-10-07 00:56:25.106049 [INFO] kazoo_node.c:625 exec: kz_uuid_setvar_multi(ab3c5ea7-e971-479a-ac42-d8ec2baedd83 ^^;ecallmgr_Account-ID=10649a107597e30ee5fcd1f743678ad1;ecallmgr_Reseller-ID=332cdb84b92ad1181a17a9ed90e7dfae;ecallmgr_Global-Resource=true;ecallmgr_Channel-Authorized=true)

2016-10-07 00:56:25.126005 [DEBUG] kazoo_node.c:1100 Sent erlang message to kazoo...@kazoo.domain.com <2.1542.187>

2016-10-07 00:56:25.126005 [INFO] kazoo_node.c:625 exec: kz_uuid_setvar_multi(ab3c5ea7-e971-479a-ac42-d8ec2baedd83 ecallmgr_Call-Interaction-ID=63643010183-9f536e04)

2016-10-07 00:56:25.326040 [DEBUG] kazoo_node.c:1100 Sent erlang message to kazoo...@kazoo.domain.com <2.1471.187>

recv 1058 bytes from udp/[212.213.XX.X2]:5060 at 00:56:29.334245:

------------------------------------------------------------------------

SIP/2.0 183 Session Progress

Call-ID: ab3c5ea7-e971-479a-ac42-d8ec2baedd83

CSeq: 97559428 INVITE

From: "0912345678" <sip:+358...@172.17.0.7>;tag=XtvmpXvK3gmjB

To: <sip:04512...@212.213.XX.X2>

Call-ID: ab3c5ea7-e971-479a-ac42-d8ec2baedd83

CSeq: 97559428 CANCEL

Reason: SIP;cause=607;text="PROGRESS_TIMEOUT"

Content-Length: 0

------------------------------------------------------------------------

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:569 (sofia/sipinterface_1/04512...@212.213.XX.X2) State Change CS_REPORTING -> CS_DESTROY

2016-10-07 00:56:36.006019 [DEBUG] switch_core_session.c:1647 Session 70 (sofia/sipinterface_1/04512...@212.213.XX.X2) Locked, Waiting on external entities

recv 401 bytes from udp/[212.213.XX.X2]:5060 at 00:56:36.030904:

------------------------------------------------------------------------

SIP/2.0 200 canceling

Via: SIP/2.0/UDP 172.17.0.7:11000;rport=11000;branch=z9hG4bKQF1S7FBtB51Zc;received=188.117.XX.XX

Oct 6 21:21:54 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.15198.184>) published to callctl(amqp://user:pass@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.15176.184>-6d559d63) via <0.24232.181>

Oct 6 21:21:54 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kapps_call_command:2471 (<0.15198.184>) waiting for bridge for 70000 ms

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_control:947 (<0.15176.184>) inserting at the tail of the control queue call command bridge

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_control:1037 (<0.15176.184>) executing call command 'bridge' ba19e0470bdd7e48821354914effda25

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_fs_bridge:49 (<0.15176.184>) creating bridge dialplan

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_config:185 (<0.15176.184>) looking up 'use_bypass_media_after_bridge' from sysconf

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_channel:159 (<0.937.0>) published to sysconf(amqp://user:pass@127.0.0.1:5672) exchange (routing key sysconf.get) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_worker:563 (<0.937.0>) published request with msg id a1f6a675640f220478097cf9c9aa3cb8 for <0.15176.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|sysconf_get:29 (<0.15206.184>) received sysconf get for ecallmgr:use_bypass_media_after_bridge from kazoo_apps@###KAZOO###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|sysconf_get:34 (<0.15206.184>) sending reply for ecallmgr.use_bypass_media_after_bridge(kazoo_apps@###KAZOO###): false

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_channel:159 (<0.15206.184>) published to targeted(amqp://user:pass@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.937.0>-f5433ed8) via <0.1103.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_worker:723 (<0.937.0>) response for msg id a1f6a675640f220478097cf9c9aa3cb8 took 7634 micro to return

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:815 (<0.1692.0>) storing {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:817 (<0.1692.0>) inserted {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:819 (<0.1692.0>) inserted origin pointers for {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:821 (<0.1692.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:596 (<0.15176.184>) building bridge endpoint: [<<"route">>,undefined,undefined,<<"+3589987654321">>,<<"loopback/0451234567">>,undefined,undefined]

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: set continue_on_fail=true

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export sip_redirect_context=context_2

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: set hangup_after_bridge=true

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export ecallmgr_Inception=${ecallmgr_Inception}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export ecallmgr_Call-Interaction-ID=${ecallmgr_Call-Interaction-ID}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: bridge {call_timeout=60,originate_timeout=60,outbound_redirect_fatal='false',ignore_early_media='true',local_var_clobber='true'}[presence_id='1000@demo1.###DOMAIN###',ignore_early_media='true',leg_timeout='60',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Call-Forward='true',ecallmgr_Authorizing-Type='device',loopback_bowout_on_execute='false',loopback_bowout='true',sdp_secure_savp_only='false',sip_invite_domain='###GATEWAY1###']loopback/0451234567

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: event Event-Name=CUSTOM,Event-Subclass=kazoo::masquerade,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=bridge

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: park

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(continue_on_fail=true)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(sip_redirect_context=context_2)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pass@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

...

[Luis Azedo]

if it was a loopback issue then maybe it was related to this https://freeswitch.org/jira/browse/FS-9451

On Fri, Oct 7, 2016 at 2:33 PM, Mikko <mikko.ra...@gbc.fi> wrote:

Thanks for your help diagnosing the problem. It looks like the problem was Freeswitch, like you suggested.
I pulled an ”apt-get upgrade” and this fixed the problem.
The new version is FreeSWITCH version: 1.6.11-19-5e413fe~64bit.

It seems that FS had some major failure when parsing the SDP content.
After upgrading, the log looks completely different after receiving the 183 message. Now it produces 3 notice lines about Pre-Answer and at least 30 debug line about the SDP parameters and state changes.
This also resolved a few other issues we were having. Such as before if a mobile user that is receiving a call cancels the call, they were directed to the next gateway, instead of terminating the call attempt and going to then next call flow element.

This morning I did a search of JIRA with a few keywords and couldn’t find anything related to this, but it seems this bug was fixed in the latest repo release.
Maybe something freaky happened when I installed it initially. Even though we have 2 instances that were exhibiting the same problems, the other instance was made by cloning the first.
Anyway I’m stoked it works now. Thanks!


On Friday, October 7, 2016 at 12:00:16 PM UTC+3, Darren Schreiber wrote:

Looking at this log, I agree with you. The progress timeout was clearly received, and acknowledged, by FS. This looks broken to me.

 

You are on 1.6.10 -17-726448d 64bit - I would suggest trying scanning the FreeSWITCH JIRA to see if there are any recent bugs with progress timeouts. If there are not, I would try another version or master of FS first, and then file a bug on their wiki as I don’t have any explanation I can think of for why this would timeout despite having the progress. One small possibility is perhaps the loopback/ usage which is involved here is causing the progress to be tracked on a temporary loopback leg while the actual timer is on an alternate leg and since the call is not answered, the loopback doesn’t bow-out, thus, there’s the issue.

 

From: Mikko <mikko.ra...@gbc.fi>
Date: Thursday, October 6, 2016 at 5:21 PM
To: 2600hz-users <2600hz...@googlegroups.com>
Cc: Darren Schreiber <dschr...@2600hz.com>

Subject: Re: Outbound calls through offnet fail progress timeout

 

Hi Darren,

 

Here is the complete FS log with only the last 2 octets of the IP obscured.

 

 

2016-10-07 00:56:25.086054 [NOTICE] kazoo_node.c:302 log|5d0d1508-ca45-4956-9041-718f17d6351c|building xferext extension: bridge {origination_caller_id_number='+358987654321',origination_caller_id_name='0912345678',ignore_early_media='false',ignore_display_updates='true',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Reseller-ID='332cdb84b92ad1181a17a9ed90e7dfae',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',effective_caller_id_number='+358987654321',effective_caller_id_name='0912345678',local_var_clobber='true'}[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/04512...@212.213.XX.X2|[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/04512...@212.213.XX.X1

EXECUTE loopback/0451234567-b export(ecallmgr_Inception=+3589876...@212.213.XX.X1)

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Inception]=[+358987654...@212.213.XX.X1]

EXECUTE loopback/0451234567-b export(ecallmgr_Call-Interaction-ID=63643010183-9f536e04)

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Call-Interaction-ID]=[63643010183-9f536e04]

EXECUTE loopback/0451234567-b bridge({origination_caller_id_number='+358987654321',origination_caller_id_name='0912345678',ignore_early_media='false',ignore_display_updates='true',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Reseller-ID='332cdb84b92ad1181a17a9ed90e7dfae',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',effective_caller_id_number='+358987654321',effective_caller_id_name='0912345678',local_var_clobber='true'}[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/04512...@212.213.XX.X2|[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/04512...@212.213.XX.X1)

2016-10-07 00:56:25.106049 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 5449

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Bridge-ID]=[2d697a833ad2106e5b1369d3571d3b6b@src.company.fi] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[kazoo_a...@kazoo.domain.com] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [sip_redirect_context]=[context_2] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Inception]=[+358987654...@212.213.XX.X1] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Call-Interaction-ID]=[63643010183-9f536e04] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Bridge-ID]=[2d697a833ad2106e5b1369d3571d3b6b@src.company.fi] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[kazoo_a...@kazoo.domain.com] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [sip_redirect_context]=[context_2] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Inception]=[+358987654...@212.213.XX.X1] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Call-Interaction-ID]=[63643010183-9f536e04] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_ivr_originate.c:2136 Parsing global variables

2016-10-07 00:56:25.106049 [DEBUG] switch_ivr_originate.c:2589 Parsing session specific variables

2016-10-07 00:56:25.106049 [NOTICE] switch_channel.c:1104 New Channel sofia/sipinterface_1/0451234567...@212.213.XX.X2 [ab3c5ea7-e971-479a-ac42-d8ec2baedd83]

2016-10-07 00:56:25.106049 [DEBUG] mod_sofia.c:4753 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State Change CS_NEW -> CS_INIT

2016-10-07 00:56:25.106049 [DEBUG] switch_ivr_originate.c:2892 sofia/sipinterface_1/0451234567...@212.213.XX.X2 Setting leg progress timeout to 10

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:543 (sofia/sipinterface_1/045123456...@212.213.XX.X2) Running State Change CS_INIT

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:586 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State INIT

2016-10-07 00:56:25.106049 [DEBUG] mod_sofia.c:90 sofia/sipinterface_1/0451234567...@212.213.XX.X2 SOFIA INIT

2016-10-07 00:56:25.106049 [DEBUG] sofia_glue.c:1276 sofia/sipinterface_1/0451234567...@212.213.XX.X2 sending invite version: 1.6.10 -17-726448d 64bit

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:40 sofia/sipinterface_1/0451234567...@212.213.XX.X2 Standard INIT

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:48 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State Change CS_INIT -> CS_ROUTING

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:586 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State INIT going to sleep

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:543 (sofia/sipinterface_1/045123456...@212.213.XX.X2) Running State Change CS_ROUTING

2016-10-07 00:56:25.106049 [DEBUG] sofia.c:6962 Channel sofia/sipinterface_1/0451234567...@212.213.XX.X2 entering state [calling][0]

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:602 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State ROUTING

2016-10-07 00:56:25.106049 [DEBUG] mod_sofia.c:143 sofia/sipinterface_1/0451234567...@212.213.XX.X2 SOFIA ROUTING

2016-10-07 00:56:25.106049 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State Change CS_ROUTING -> CS_CONSUME_MEDIA

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:602 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State ROUTING going to sleep

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:543 (sofia/sipinterface_1/045123456...@212.213.XX.X2) Running State Change CS_CONSUME_MEDIA

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:621 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State CONSUME_MEDIA

2016-10-07 00:56:25.106049 [DEBUG] switch_core_state_machine.c:621 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State CONSUME_MEDIA going to sleep

2016-10-07 00:56:29.326056 [DEBUG] sofia.c:6962 Channel sofia/sipinterface_1/0451234567...@212.213.XX.X2 entering state [proceeding][183]

2016-10-07 00:56:29.326056 [DEBUG] sofia.c:6972 Remote SDP:

v=0

o=- 128369331693981 128369331693981 IN IP4 109.69.XX.X2

s=-

c=IN IP4 109.69.XX.X2

t=0 0

m=audio 20208 RTP/AVP 8 101

a=rtpmap:8 PCMA/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

a=X-sqn:0

a=X-cap: 1 audio RTP/AVP 100

a=X-cpar: a=rtpmap:100 X-NSE/8000

a=X-cpar: a=fmtp:100 192-194,200-202

a=X-cap: 2 image udptl t38

 

2016-10-07 00:56:36.006019 [NOTICE] switch_ivr_originate.c:322 Hangup sofia/sipinterface_1/0451234567...@212.213.XX.X2 [CS_CONSUME_MEDIA] [PROGRESS_TIMEOUT]

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:543 (sofia/sipinterface_1/045123456...@212.213.XX.X2) Running State Change CS_HANGUP

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:809 (sofia/sipinterface_1/045123456...@212.213.XX.X2) Callstate Change DOWN -> HANGUP

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:811 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State HANGUP

2016-10-07 00:56:36.006019 [DEBUG] mod_sofia.c:438 Channel sofia/sipinterface_1/0451234567...@212.213.XX.X2 hanging up, cause: PROGRESS_TIMEOUT

2016-10-07 00:56:36.006019 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/sipinterface_1/0451234567...@212.213.XX.X2

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:60 sofia/sipinterface_1/0451234567...@212.213.XX.X2 Standard HANGUP, cause: PROGRESS_TIMEOUT

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:811 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State HANGUP going to sleep

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:578 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State Change CS_HANGUP -> CS_REPORTING

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:543 (sofia/sipinterface_1/045123456...@212.213.XX.X2) Running State Change CS_REPORTING

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:897 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State REPORTING

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:174 sofia/sipinterface_1/0451234567...@212.213.XX.X2 Standard REPORTING, cause: PROGRESS_TIMEOUT

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:897 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State REPORTING going to sleep

send 376 bytes to udp/[212.213.XX.X2]:5060 at 00:56:36.026067:

------------------------------------------------------------------------

CANCEL sip:04512...@212.213.XX.X2 SIP/2.0

Via: SIP/2.0/UDP 172.17.0.7:11000;rport;branch=z9hG4bKQF1S7FBtB51Zc

Max-Forwards: 70

From: "0912345678" <sip:+358...@172.17.0.7>;tag=XtvmpXvK3gmjB

To: <sip:04512...@212.213.XX.X2>

Call-ID: ab3c5ea7-e971-479a-ac42-d8ec2baedd83

CSeq: 97559428 CANCEL

Reason: SIP;cause=607;text="PROGRESS_TIMEOUT"

Content-Length: 0

------------------------------------------------------------------------

2016-10-07 00:56:36.006019 [DEBUG] switch_core_state_machine.c:569 (sofia/sipinterface_1/045123456...@212.213.XX.X2) State Change CS_REPORTING -> CS_DESTROY

2016-10-07 00:56:36.006019 [DEBUG] switch_core_session.c:1647 Session 70 (sofia/sipinterface_1/045123456...@212.213.XX.X2) Locked, Waiting on external entities

recv 401 bytes from udp/[212.213.XX.X2]:5060 at 00:56:36.030904:

------------------------------------------------------------------------

SIP/2.0 200 canceling

Via: SIP/2.0/UDP 172.17.0.7:11000;rport=11000;branch=z9hG4bKQF1S7FBtB51Zc;received=188.117.XX.XX

From: "0912345678" <sip:+358...@172.17.0.7>;tag=XtvmpXvK3gmjB

To: <sip:04512...@212.213.XX.X2>;tag=eed6322f0191e495094566a9c9fe2820-9d64

Call-ID: ab3c5ea7-e971-479a-ac42-d8ec2baedd83

CSeq: 97559428 CANCEL

Server: kamailio (4.1.6 (i386/solaris))

Content-Length: 0

------------------------------------------------------------------------

2016-10-07 00:56:36.026238 [DEBUG] switch_ivr_originate.c:3759 Originate Resulted in Error Cause: 607 [PROGRESS_TIMEOUT]

2016-10-07 00:56:36.026238 [DEBUG] switch_ivr_originate.c:2589 Parsing session specific variables

2016-10-07 00:56:36.026238 [NOTICE] switch_core_session.c:1665 Session 70 (sofia/sipinterface_1/045123456...@212.213.XX.X2) Ended

2016-10-07 00:56:36.026238 [NOTICE] switch_core_session.c:1669 Close Channel sofia/sipinterface_1/0451234567...@212.213.XX.X2 [CS_DESTROY]

2016-10-07 00:56:36.026238 [DEBUG] switch_core_state_machine.c:700 (sofia/sipinterface_1/045123456...@212.213.XX.X2) Running State Change CS_DESTROY

...

--

You received this message because you are subscribed to the Google Groups "2600hz-users" group.

To unsubscribe from this group and stop receiving emails from it, send an email to 2600hz-users+unsubscribe@googlegroups.com.

[Darren Schreiber]

We are looking at FS-9203 if you want to track it down, and it’s agreed that the bug is known and already fixed so this is likely the issue indeed.

 

From: Mikko <mikko.ra...@gbc.fi>
Date: Friday, October 7, 2016 at 9:33 AM
To: 2600hz-users <2600hz...@googlegroups.com>
Cc: "mikko.ra...@gbc.fi" <mikko.ra...@gbc.fi>, Darren Schreiber <dschr...@2600hz.com>
Subject: Re: Outbound calls through offnet fail progress timeout

 

Thanks for your help diagnosing the problem. It looks like the problem was Freeswitch, like you suggested.
I pulled an ”apt-get upgrade” and this fixed the problem.
The new version is FreeSWITCH version: 1.6.11-19-5e413fe~64bit.

It seems that FS had some major failure when parsing the SDP content.
After upgrading, the log looks completely different after receiving the 183 message. Now it produces 3 notice lines about Pre-Answer and at least 30 debug line about the SDP parameters and state changes.
This also resolved a few other issues we were having. Such as before if a mobile user that is receiving a call cancels the call, they were directed to the next gateway, instead of terminating the call attempt and going to then next call flow element.

This morning I did a search of JIRA with a few keywords and couldn’t find anything related to this, but it seems this bug was fixed in the latest repo release.
Maybe something freaky happened when I installed it initially. Even though we have 2 instances that were exhibiting the same problems, the other instance was made by cloning the first.
Anyway I’m stoked it works now. Thanks!


On Friday, October 7, 2016 at 12:00:16 PM UTC+3, Darren Schreiber wrote:

Looking at this log, I agree with you. The progress timeout was clearly received, and acknowledged, by FS. This looks broken to me.

 

You are on 1.6.10 -17-726448d 64bit - I would suggest trying scanning the FreeSWITCH JIRA to see if there are any recent bugs with progress timeouts. If there are not, I would try another version or master of FS first, and then file a bug on their wiki as I don’t have any explanation I can think of for why this would timeout despite having the progress. One small possibility is perhaps the loopback/ usage which is involved here is causing the progress to be tracked on a temporary loopback leg while the actual timer is on an alternate leg and since the call is not answered, the loopback doesn’t bow-out, thus, there’s the issue.

 

From: Mikko <mikko.ra...@gbc.fi>
Date: Thursday, October 6, 2016 at 5:21 PM
To: 2600hz-users <2600hz...@googlegroups.com>
Cc: Darren Schreiber <dschr...@2600hz.com>
Subject: Re: Outbound calls through offnet fail progress timeout

 

Hi Darren,

 

Here is the complete FS log with only the last 2 octets of the IP obscured.

 

 

2016-10-07 00:56:25.086054 [NOTICE] kazoo_node.c:302 log|5d0d1508-ca45-4956-9041-718f17d6351c|building xferext extension: bridge {origination_caller_id_number='+358987654321',origination_caller_id_name='0912345678',ignore_early_media='false',ignore_display_updates='true',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Reseller-ID='332cdb84b92ad1181a17a9ed90e7dfae',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',effective_caller_id_number='+358987654321',effective_caller_id_name='0912345678',local_var_clobber='true'}[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/04512...@212.213.XX.X2|[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/04512...@212.213.XX.X1

EXECUTE loopback/0451234567-b export(ecallmgr_Inception=+358987654321@212.213.XX.X1)

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Inception]=[+358987654321@212.213.XX.X1]

EXECUTE loopback/0451234567-b export(ecallmgr_Call-Interaction-ID=63643010183-9f536e04)

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [ecallmgr_Call-Interaction-ID]=[63643010183-9f536e04]

EXECUTE loopback/0451234567-b bridge({origination_caller_id_number='+358987654321',origination_caller_id_name='0912345678',ignore_early_media='false',ignore_display_updates='true',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Reseller-ID='332cdb84b92ad1181a17a9ed90e7dfae',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',effective_caller_id_number='+358987654321',effective_caller_id_name='0912345678',local_var_clobber='true'}[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/04512...@212.213.XX.X2|[leg_progress_timeout='10',ecallmgr_Global-Resource='true',ecallmgr_Resource-ID='XXX-carrier',ecallmgr_E164-Destination='0451234567',ecallmgr_Original-Number='0451234567',ecallmgr_Matched-Number='0451234567',absolute_codec_string='^^:PCMA:PCMU',effective_callee_id_number='0451234567',effective_callee_id_name='0451234567']sofia/sipinterface_1/04512...@212.213.XX.X1)

2016-10-07 00:56:25.106049 [DEBUG] kazoo_event_stream.c:245 increased event stream buffer size to 5449

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Bridge-ID]=[2d697a833ad2106e...@src.company.fi] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[kazoo...@kazoo.domain.com] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [sip_redirect_context]=[context_2] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Inception]=[+358987654321@212.213.XX.X1] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Call-Interaction-ID]=[63643010183-9f536e04] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Bridge-ID]=[2d697a833ad2106e...@src.company.fi] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Ecallmgr-Node]=[kazoo...@kazoo.domain.com] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [sip_redirect_context]=[context_2] to event

2016-10-07 00:56:25.106049 [DEBUG] switch_channel.c:1250 loopback/0451234567-b EXPORTING[export_vars] [ecallmgr_Inception]=[+358987654321@212.213.XX.X1] to event

Oct 6 21:21:54 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.15198.184>) published to callctl(amqp://user:pa...@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.15176.184>-6d559d63) via <0.24232.181>

Oct 6 21:21:54 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kapps_call_command:2471 (<0.15198.184>) waiting for bridge for 70000 ms

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15176.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_control:947 (<0.15176.184>) inserting at the tail of the control queue call command bridge

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_control:1037 (<0.15176.184>) executing call command 'bridge' ba19e0470bdd7e48821354914effda25

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_fs_bridge:49 (<0.15176.184>) creating bridge dialplan

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_config:185 (<0.15176.184>) looking up 'use_bypass_media_after_bridge' from sysconf

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_channel:159 (<0.937.0>) published to sysconf(amqp://user:pa...@127.0.0.1:5672) exchange (routing key sysconf.get) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_worker:563 (<0.937.0>) published request with msg id a1f6a675640f220478097cf9c9aa3cb8 for <0.15176.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|sysconf_get:29 (<0.15206.184>) received sysconf get for ecallmgr:use_bypass_media_after_bridge from kazoo_apps@###KAZOO###

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|sysconf_get:34 (<0.15206.184>) sending reply for ecallmgr.use_bypass_media_after_bridge(kazoo_apps@###KAZOO###): false

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_channel:159 (<0.15206.184>) published to targeted(amqp://user:pa...@127.0.0.1:5672) exchange (routing key kazoo_apps@###KAZOO###-<0.937.0>-f5433ed8) via <0.1103.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |a1f6a675640f220478097cf9c9aa3cb8|kz_amqp_worker:723 (<0.937.0>) response for msg id a1f6a675640f220478097cf9c9aa3cb8 took 7634 micro to return

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:815 (<0.1692.0>) storing {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>} for 3600s

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:817 (<0.1692.0>) inserted {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:819 (<0.1692.0>) inserted origin pointers for {ecallmgr_config,<<"use_bypass_media_after_bridge">>,<<"kazoo_apps@###KAZOO###">>}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |50a60e4ce52ba3e5|kz_cache:821 (<0.1692.0>) exec store callbacks

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:596 (<0.15176.184>) building bridge endpoint: [<<"route">>,undefined,undefined,<<"+3589987654321">>,<<"loopback/0451234567">>,undefined,undefined]

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: set continue_on_fail=true

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export sip_redirect_context=context_2

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: set hangup_after_bridge=true

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export ecallmgr_Inception=${ecallmgr_Inception}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: export ecallmgr_Call-Interaction-ID=${ecallmgr_Call-Interaction-ID}

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: bridge {call_timeout=60,originate_timeout=60,outbound_redirect_fatal='false',ignore_early_media='true',local_var_clobber='true'}[presence_id='1000@demo1.###DOMAIN###',ignore_early_media='true',leg_timeout='60',ecallmgr_Authorizing-ID='c7977a34493ff042b898cf74e32f2d94',ecallmgr_Owner-ID='b27257e420981374d1f81671cfa39a0b',ecallmgr_Account-ID='10649a107597e30ee5fcd1f743678ad1',ecallmgr_Call-Forward='true',ecallmgr_Authorizing-Type='device',loopback_bowout_on_execute='false',loopback_bowout='true',sdp_secure_savp_only='false',sip_invite_domain='###GATEWAY1###']loopback/0451234567

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: event Event-Name=CUSTOM,Event-Subclass=kazoo::masquerade,kazoo_event_name=CHANNEL_EXECUTE_COMPLETE,kazoo_application_name=bridge

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:90 (<0.15176.184>) building xferext on node frees...@10.0.0.1: park

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(continue_on_fail=true)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_call_events:713 (<0.15175.184>) publishing call event channel_execute 'set(sip_redirect_context=context_2)'

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_channel:159 (<0.937.0>) published to callevt(amqp://user:pa...@127.0.0.1:5672) exchange (routing key call.CHANNEL_EXECUTE.7a6c5abc4b42a4816961d5f91d425db2%40###CALLER###) via <0.1044.0>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|kz_amqp_worker:624 (<0.937.0>) published message 1475778115046007 for <0.15175.184>

Oct 6 21:21:55 kazoo-server 2600hz[18190]: |7a6c5abc4b42a4816961d5f91d425db2@###CALLER###|ecallmgr_util:1167 (<0.15175.184>) adding diversion sip:09987654321@###DOMAIN2###;user=phone to SIP headers

...