480 Temporarily Unavailable

[Paul Kramer]

Hi all has anyone ever had any issues with phones receiving a 480 Temporarily Unavailable message when trying to call out? The phones are able to receive but not make calls. The phones are all registering successfully.

[Paul Kramer]

Here's the actual SIP message from the Mitel 5340 SIP phone.

SIP/2.0 480 Temporarily Unavailable

Via: SIP/2.0/UDP <IP>:7529;branch=z9hG4bKf5579871

Max-Forwards: 70

From: "105" <sip:ci...@kazoo.com>;tag=0024142e31dd0f0dec725b41-3c9e5d71

To: <sip:1...@kazoo.com>;tag=189p1m7aU6eUB

Call-ID: 0024142e-31dd000d...@192.168.13.100

CSeq: 102 INVITE

User-Agent: 2600hz

Accept: application/sdp

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

Supported: precondition, path, replaces

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

Reason: Q.850;cause=16;text="NORMAL_CLEARING"

Content-Length: 0

Remote-Party-ID: "102" <sip:1...@kazoo.com>;party=calling;privacy=off;screen=no

[Darren Schreiber]

Where is the packet that started this? (the INVITE)?

Also, please do this:

grep "0024142e-31dd000d...@192.168.13.100" /var/log/2600hz-platform.log

on your apps servers and post that.

--

Darren Schreiber

CEO / Co-Founder

 visit: www.2600hz.com

 sip:dar...@2600hz.com

 tel: 415-886-7901

[Paul Kramer]

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_fs_route:170 (<0.28359.0>) processing fetch request c5ac9815-76df-41e9-b3d3-ca6bee009bdc (call 1db90000...@host.domain.com) from frees...@host.domain.com

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:85 (<0.300.0>) publish to broker amqp://guest:guest@<ip_address>:5672, exchange 'callmgr' with routing key 'route.req.kazoo%2Eulkramer%2Ecom' via channel <0.312.0>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_worker:202 (<0.300.0>) published request with msg id c5ac9815-76df-41e9-b3d3-ca6bee009bdc for <0.28359.0>

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|reg_route_req:26 (<0.5408.5>) trying to see if this route req is an auth-by-ip'd device: 220.245.122.58

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|reg_route_req:57 (<0.5408.5>) route req has account id already: ef9c7eaf24b2d643166658c2f9847c3f

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|whapps_config:370 (<0.5411.5>) fetch db config for number_manager

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_route_req:20 (<0.5411.5>) received route request

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_util:365 (<0.5411.5>) searching for callflow in account%2Fef%2F9c%2F7eaf24b2d643166658c2f9847c3f to satisfy '105'

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_route_req:28 (<0.5411.5>) callflow 4f532320d8038f6d855733041410be16 in ef9c7eaf24b2d643166658c2f9847c3f satisfies request

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|whapps_config:370 (<0.5411.5>) fetch db config for callflow

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|wh_amqp_connection:85 (<0.5411.5>) publish to broker amqp://guest:guest@<ip_address>:5672, exchange 'targeted' with routing key 'amq.gen-Q7QT1EtOty2xBH5f-k9DB9' via channel <0.290.0>

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_route_req:77 (<0.5411.5>) sent route response to park the call

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_config:73 (<0.28359.0>) looking up authz_enabled from sysconf

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_fs_route:207 (<0.28359.0>) sending XML to frees...@host.domain.com: <document type="freeswitch/xml"><section name="dialplan" description="Route Park Response"><context name="context_2"><extension name="park"><condition><action application="log" data="NOTICE log|${uuid}|ecal...@host.domain.com won call control"/><action application="park"/></condition></extension></context></section></document>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_fs_route:210 (<0.28359.0>) node frees...@host.domain.com accepted our route (authzed), starting control and events

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_fs_route:215 (<0.28359.0>) created new billing id 441f89e42fd3f5cd6a50d0a05667d73e for channel 1db90000...@host.domain.com

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_util:98 (<0.28359.0>) execute on node frees...@host.domain.com: export(ecallmgr_Billing-ID=441f89e42fd3f5cd6a50d0a05667d73e)

Oct 24 02:44:12 kazoo 2600hz[2520]: |frees...@host.domain.com|ecallmgr_fs_node:248 (<0.1247.0>) received channel create event: 1db90000...@host.domain.com

Oct 24 02:44:12 kazoo 2600hz[2520]: |frees...@host.domain.com|ecallmgr_fs_node:515 (<0.1247.0>) ignoring start events for 1db90000...@host.domain.com: {error,not_found}

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_authz:38 (<0.28364.0>) config ecallmgr.authz is disabled

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_authz:146 (<0.28364.0>) channel authorization succeeded, allowing call

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_control:262 (<0.28366.0>) starting call control listener

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:223 (<0.28366.0>) starting new AMQP channel for process <0.28366.0>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_events:167 (<0.28367.0>) starting call events listener

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|gen_listener:321 (<0.28366.0>) AMQP queue created: amq.gen-Atn6UgC1Bt9MHjP9fBIBMC

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:173 (<0.28366.0>) attempting to create new topic exchange 'callevt' via channel <0.98.0>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:173 (<0.28366.0>) attempting to create new topic exchange 'callmgr' via channel <0.98.0>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:109 (<0.28366.0>) bind 'amq.gen-Atn6UgC1Bt9MHjP9fBIBMC' to exchange 'callevt' with routing key 'call.event.1db90000-3f03c773%40kazoo%2Eulkramer%2Ecom' on broker amqp://guest:guest@<ip_address>:5672

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:173 (<0.28366.0>) attempting to create new direct exchange 'callctl' via channel <0.98.0>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:109 (<0.28366.0>) bind 'amq.gen-Atn6UgC1Bt9MHjP9fBIBMC' to exchange 'callctl' with routing key 'amq.gen-Atn6UgC1Bt9MHjP9fBIBMC' on broker amqp://guest:guest@<ip_address>:5672

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:173 (<0.28366.0>) attempting to create new direct exchange 'targeted' via channel <0.98.0>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:109 (<0.28366.0>) bind 'amq.gen-Atn6UgC1Bt9MHjP9fBIBMC' to exchange 'targeted' with routing key 'amq.gen-Atn6UgC1Bt9MHjP9fBIBMC' on broker amqp://guest:guest@<ip_address>:5672

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|gen_listener:495 (<0.28366.0>) consuming from our queue

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_fs_route:248 (<0.28359.0>) sending route_win to amq.gen-Qk42cxe-ZDN7ZGjj7mSXSf

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:85 (<0.28359.0>) publish to broker amqp://guest:guest@<ip_address>:5672, exchange 'targeted' with routing key 'amq.gen-Qk42cxe-ZDN7ZGjj7mSXSf' via channel <0.94.0>

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_route_win:20 (<0.5421.5>) received route win

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_route_win:23 (<0.5421.5>) bootstrapping callflow executer

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_attributes:396 (<0.5421.5>) object 4639e15fa0abf7ff102b1d6c98427f2c is owned by 28bcc7bcdb1e39a89d679af62831b2f4

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_attributes:209 (<0.5421.5>) find external caller id on 4639e15fa0abf7ff102b1d6c98427f2c, 28bcc7bcdb1e39a89d679af62831b2f4, ef9c7eaf24b2d643166658c2f9847c3f

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_attributes:457 (<0.5421.5>) find friendly name on 28bcc7bcdb1e39a89d679af62831b2f4, 4639e15fa0abf7ff102b1d6c98427f2c

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_attributes:464 (<0.5421.5>) using name 'Account Admin' from 28bcc7bcdb1e39a89d679af62831b2f4

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_attributes:124 (<0.5421.5>) found CID 5340 in phone_numbers doc

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_attributes:396 (<0.5421.5>) object 4639e15fa0abf7ff102b1d6c98427f2c is owned by 28bcc7bcdb1e39a89d679af62831b2f4

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_attributes:361 (<0.5421.5>) find moh attr media_id on 4639e15fa0abf7ff102b1d6c98427f2c, 28bcc7bcdb1e39a89d679af62831b2f4, ef9c7eaf24b2d643166658c2f9847c3f

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_attributes:365 (<0.5421.5>) unable to find moh attribute media_id

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|whapps_call_command:1794 (<0.5421.5>) cf_exe_pid down, publish as self(<0.5421.5>)

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|wh_amqp_connection:85 (<0.5421.5>) publish to broker amqp://guest:guest@<ip_address>:5672, exchange 'callctl' with routing key 'amq.gen-Atn6UgC1Bt9MHjP9fBIBMC' via channel <0.290.0>

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_route_win:80 (<0.5421.5>) call has been setup, passing control to callflow executer

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_exe:248 (<0.5430.5>) executing callflow 4f532320d8038f6d855733041410be16

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_exe:249 (<0.5430.5>) account id ef9c7eaf24b2d643166658c2f9847c3f

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_exe:250 (<0.5430.5>) request 1...@host.domain.com

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_exe:251 (<0.5430.5>) to 1...@host.domain.com

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_control:639 (<0.28366.0>) received immediate call command 'set'

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_exe:252 (<0.5430.5>) from 53...@host.domain.com

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_exe:253 (<0.5430.5>) CID 5340 5340

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_control:764 (<0.28366.0>) executing call command 'set' a64855ed02cef75d7f74fd7e2a4e6a94

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_exe:254 (<0.5430.5>) inception on-net

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_exe:255 (<0.5430.5>) authorizing id 4639e15fa0abf7ff102b1d6c98427f2c

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_util:98 (<0.28366.0>) execute on node frees...@host.domain.com: multiset(^^|effective_caller_id_name=Account Admin|effective_caller_id_number=5340|ecallmgr_Billing-ID=441f89e42fd3f5cd6a50d0a05667d73e|ecallmgr_Username=5340|ecallmgr_Realm=host.domain.com|ecallmgr_Account-ID=ef9c7eaf24b2d643166658c2f9847c3f|ecallmgr_Authorizing-Type=device|ecallmgr_Inception=on-net|ecallmgr_Authorizing-ID=4639e15fa0abf7ff102b1d6c98427f2c|ecallmgr_Owner-ID=28bcc7bcdb1e39a89d679af62831b2f4)

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|wh_amqp_connection:223 (<0.5430.5>) starting new AMQP channel for process <0.5430.5>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_events:278 (<0.28367.0>) listening to channel events from frees...@host.domain.com

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:85 (<0.28367.0>) publish to broker amqp://guest:guest@<ip_address>:5672, exchange 'callevt' with routing key 'publisher.usurp.1db90000-3f03c773%40kazoo%2Eulkramer%2Ecom' via channel <0.94.0>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:223 (<0.28367.0>) starting new AMQP channel for process <0.28367.0>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|gen_listener:321 (<0.28367.0>) AMQP queue created: amq.gen-wqwOlezYkRw-o3KZMfN9rl

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|gen_listener:321 (<0.5430.5>) AMQP queue created: amq.gen-wj9OOd74LUlSHb0ZMdCh29

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:173 (<0.28367.0>) attempting to create new topic exchange 'callevt' via channel <0.98.0>

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|wh_amqp_connection:173 (<0.5430.5>) attempting to create new topic exchange 'callevt' via channel <0.104.0>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:173 (<0.28367.0>) attempting to create new topic exchange 'callmgr' via channel <0.98.0>

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|wh_amqp_connection:173 (<0.5430.5>) attempting to create new topic exchange 'callmgr' via channel <0.104.0>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:109 (<0.28367.0>) bind 'amq.gen-wqwOlezYkRw-o3KZMfN9rl' to exchange 'callevt' with routing key 'publisher.usurp.*' on broker amqp://guest:guest@<ip_address>:5672

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|wh_amqp_connection:109 (<0.5430.5>) bind 'amq.gen-wj9OOd74LUlSHb0ZMdCh29' to exchange 'callevt' with routing key 'call.event.1db90000-3f03c773%40kazoo%2Eulkramer%2Ecom' on broker amqp://guest:guest@<ip_address>:5672

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|gen_listener:495 (<0.28367.0>) consuming from our queue

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|wh_amqp_connection:109 (<0.5430.5>) bind 'amq.gen-wj9OOd74LUlSHb0ZMdCh29' to exchange 'callevt' with routing key 'call.cdr.1db90000-3f03c773%40kazoo%2Eulkramer%2Ecom' on broker amqp://guest:guest@<ip_address>:5672

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|wh_amqp_connection:109 (<0.5430.5>) bind 'amq.gen-wj9OOd74LUlSHb0ZMdCh29' to exchange 'callevt' with routing key 'publisher.usurp.1db90000-3f03c773%40kazoo%2Eulkramer%2Ecom' on broker amqp://guest:guest@<ip_address>:5672

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|wh_amqp_connection:173 (<0.5430.5>) attempting to create new direct exchange 'targeted' via channel <0.104.0>

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|wh_amqp_connection:109 (<0.5430.5>) bind 'amq.gen-wj9OOd74LUlSHb0ZMdCh29' to exchange 'targeted' with routing key 'amq.gen-wj9OOd74LUlSHb0ZMdCh29' on broker amqp://guest:guest@<ip_address>:5672

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|gen_listener:495 (<0.5430.5>) consuming from our queue

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_exe:532 (<0.5430.5>) moving to action cf_device

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_device:32 (<0.5437.5>) error bridging to device: owner_called_self

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_exe:337 (<0.5430.5>) continuing to child _

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_exe:340 (<0.5430.5>) wildcard child does not exist, we are lost...

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|wh_amqp_connection:85 (<0.5430.5>) publish to broker amqp://guest:guest@<ip_address>:5672, exchange 'callctl' with routing key 'amq.gen-Atn6UgC1Bt9MHjP9fBIBMC' via channel <0.5434.5>

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_exe:494 (<0.5430.5>) callflow execution has been stopped: normal

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|gen_listener:551 (<0.5430.5>) terminating binding call ([{callid,<<"1db90000...@host.domain.com">>}])

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|gen_listener:551 (<0.5430.5>) terminating binding self ([])

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|gen_listener:554 (<0.5430.5>) cf_exe terminated cleanly, going down

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_control:442 (<0.28366.0>) evt set not app undefined

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_control:305 (<0.28366.0>) updating controller queue to amq.gen-wj9OOd74LUlSHb0ZMdCh29

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_control:639 (<0.28366.0>) received immediate call command 'hangup'

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_control:764 (<0.28366.0>) executing call command 'hangup' ce97c8b8a942fe04968be65c6f5cfdb6

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_util:93 (<0.28366.0>) terminate call on node frees...@host.domain.com

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_events:451 (<0.28367.0>) publishing call event channel_hangup

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:85 (<0.28367.0>) publish to broker amqp://guest:guest@<ip_address>:5672, exchange 'callevt' with routing key 'call.event.1db90000-3f03c773%40kazoo%2Eulkramer%2Ecom' via channel <0.28377.0>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_events:455 (<0.28367.0>) publishing call event channel_execute_complete 'park(<<>>)' result: _none_

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:85 (<0.28367.0>) publish to broker amqp://guest:guest@<ip_address>:5672, exchange 'callevt' with routing key 'call.event.1db90000-3f03c773%40kazoo%2Eulkramer%2Ecom' via channel <0.28377.0>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_events:451 (<0.28367.0>) publishing call event channel_hangup_complete

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:85 (<0.28367.0>) publish to broker amqp://guest:guest@<ip_address>:5672, exchange 'callevt' with routing key 'call.event.1db90000-3f03c773%40kazoo%2Eulkramer%2Ecom' via channel <0.28377.0>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_events:209 (<0.28367.0>) our channel has been destroyed, preparing to shutdown

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_control:215 (<0.28387.0>) control queue <0.28366.0> channel execute completion for 'park'

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_control:442 (<0.28366.0>) evt park not app undefined

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_cdr:53 (<0.28390.0>) publising cdr: [{<<"Custom-Channel-Vars">>,{[{<<"Owner-ID">>,<<"28bcc7bcdb1e39a89d679af62831b2f4">>},{<<"Authorizing-ID">>,<<"4639e15fa0abf7ff102b1d6c98427f2c">>},{<<"Inception">>,<<"on-net">>},{<<"Authorizing-Type">>,<<"device">>},{<<"Account-ID">>,<<"ef9c7eaf24b2d643166658c2f9847c3f">>},{<<"Realm">>,<<"host.domain.com">>},{<<"Username">>,<<"5340">>},{<<"Billing-ID">>,<<"441f89e42fd3f5cd6a50d0a05667d73e">>}]}},{<<"Digits-Dialed">>,<<"none">>},{<<"Ringing-Seconds">>,<<"0">>},{<<"Billing-Seconds">>,<<"0">>},{<<"Duration-Seconds">>,<<"1">>},{<<"User-Agent">>,<<"Mitel-5340-SIP-Phone 05.01.00.16 08000F3B50CE">>},{<<"Caller-ID-Name">>,<<"Account Admin">>},{<<"Caller-ID-Number">>,<<"5340">>},{<<"From-Uri">>,<<"53...@host.domain.com">>},{<<"To-Uri">>,<<"1...@host.domain.com">>},{<<"Remote-SDP">>,<<"v=0\r\no=5340 1351032414 1351032413 IN IP4 220.245.122.58\r\ns=SIP Call\r\ni=(o=IN IP4 192.168.10.103)\r\nc=IN IP4 220.245.122.58\r\nt=0 0\r\na=sendrecv\r\nm=audio 15266 RTP/AVP 0 8 18 101\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:18 G729/8000\r\na=rtpmap:101 telephone-event/8000\r\n">>},{<<"Call-Direction">>,<<"inbound">>},{<<"Timestamp">>,<<"63518265904">>},{<<"Call-ID">>,<<"1db90000...@host.domain.com">>},{<<"Hangup-Cause">>,<<"NORMAL_CLEARING">>},{<<"Handling-Server-Name">>,<<"host.domain.com">>},{<<"Server-ID">>,<<>>},{<<"Event-Category">>,<<"call_detail">>},{<<"Event-Name">>,<<"cdr">>},{<<"App-Name">>,<<"ecallmgr">>},{<<"App-Version">>,<<"0.8.0">>},{<<"Node">>,<<"ecal...@host.domain.com">>}]

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:85 (<0.28390.0>) publish to broker amqp://guest:guest@<ip_address>:5672, exchange 'callevt' with routing key 'call.cdr.1db90000-3f03c773%40kazoo%2Eulkramer%2Ecom' via channel <0.94.0>

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|whapps_config:370 (<0.5445.5>) fetch db config for hangups

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cdr_listener:70 (<0.5441.5>) saving CDR to account%2Fef%2F9c%2F7eaf24b2d643166658c2f9847c3f

Oct 24 02:44:12 kazoo 2600hz[2520]: |frees...@host.domain.com|ecallmgr_fs_node:257 (<0.1247.0>) received channel destroyed: 1db90000...@host.domain.com

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_events:451 (<0.28391.0>) publishing call event channel_destroy

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|wh_amqp_connection:85 (<0.28391.0>) publish to broker amqp://guest:guest@<ip_address>:5672, exchange 'callevt' with routing key 'call.event.1db90000-3f03c773%40kazoo%2Eulkramer%2Ecom' via channel <0.94.0>

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_control:387 (<0.28366.0>) our channel has been destroyed, executing any post-hangup commands

Oct 24 02:44:12 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_control:831 (<0.28366.0>) started post hangup keep alive timer for 5000ms

Oct 24 02:44:13 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_events:348 (<0.28367.0>) goodbye and thanks for all the fish

Oct 24 02:44:13 kazoo 2600hz[2520]: |1db90000...@host.domain.com|gen_listener:551 (<0.28367.0>) terminating binding call ([{restrict_to,[publisher_usurp]}])

Oct 24 02:44:13 kazoo 2600hz[2520]: |1db90000...@host.domain.com|gen_listener:554 (<0.28367.0>) ecallmgr_call_events terminated cleanly, going down

Oct 24 02:44:13 kazoo 2600hz[12657]: |1db90000...@host.domain.com|whapps_config:370 (<0.5443.5>) fetch db config for jonny5

Oct 24 02:44:13 kazoo 2600hz[12657]: |1db90000...@host.domain.com|j5_call_cdr:85 (<0.5443.5>) final session 441f89e42fd3f5cd6a50d0a05667d73e rate at $0.0/60s with minumim 0s and surcharge $0.0 for 0 secs: $0.0

Oct 24 02:44:13 kazoo 2600hz[12657]: |1db90000...@host.domain.com|j5_call_cdr:37 (<0.5443.5>) session 441f89e42fd3f5cd6a50d0a05667d73e cost $0.0 and we charged $0.0, no update for account ef9c7eaf24b2d643166658c2f9847c3f

Oct 24 02:44:17 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_control:542 (<0.28366.0>) no new commands received after channel destruction, our job here is done

Oct 24 02:44:17 kazoo 2600hz[2520]: |1db90000...@host.domain.com|ecallmgr_call_control:584 (<0.28366.0>) control queue was up for 5380277 microseconds

Oct 24 02:44:17 kazoo 2600hz[2520]: |1db90000...@host.domain.com|gen_listener:551 (<0.28366.0>) terminating binding call ([{callid,<<"1db90000...@host.domain.com">>},{restrict_to,[events]}])

Oct 24 02:44:17 kazoo 2600hz[2520]: |1db90000...@host.domain.com|gen_listener:551 (<0.28366.0>) terminating binding dialplan ([])

Oct 24 02:44:17 kazoo 2600hz[2520]: |1db90000...@host.domain.com|gen_listener:551 (<0.28366.0>) terminating binding self ([])

Oct 24 02:44:17 kazoo 2600hz[2520]: |1db90000...@host.domain.com|gen_listener:554 (<0.28366.0>) ecallmgr_call_control terminated cleanly, going down

And the associated invite....

@@&iLuEC4z:28WMuINVITE sip:1...@host.domain.com SIP/2.0

Via:SIP/2.0/UDP <public_ip>:61557;rport;branch=z9hG4bK1dba0052

From:"5340" <sip:53...@host.domain.com>;tag=50871db9-a4-2c6e7c9c

To:<sip:1...@host.domain.com>

Contact:"5340" <sip:5340@<public_ip>:61557;transport=UDP>

Call-ID:1db90000...@host.domain.com

Subject:sip phone call

CSeq:128804807 INVITE

User-Agent:Mitel-5340-SIP-Phone 05.01.00.16 08000F3B50CE

Proxy-Authorization: Digest username="5340", realm="host.domain.com", nonce="dfb8d462-23ef-49b3-a7c4-aca0c27aadd3", uri="sip:1...@host.domain.com", qop=auth, nc=00000001, cnonce="29-1351032250", response="a7a5c46be39ea48f346ebadb0fcf3ca9", opaque="", algorithm=MD5

Allow:INVITE,ACK,CANCEL,BYE,OPTIONS,REFER,NOTIFY,PRACK,UPDATE

Allow-Events:talk,hold,conference

Supported:timer,100rel,replaces

Session-Expires: 1800;refresher=uas

Min-SE: 90

Max-Forwards:70

Content-Type:application/sdp

Content-Length:278

v=0

o=5340 1351032414 1351032413 IN IP4 <public_ip>

s=SIP Call

i=(o=IN IP4 192.168.10.103)

c=IN IP4 <public_IP>

t=0 0

a=sendrecv

m=audio 15266 RTP/AVP 0 8 18 101

a=rtpmap:0 PCMU/8000

a=rtpmap:8 PCMA/8000

a=rtpmap:18 G729/8000

a=rtpmap:101 telephone-event/8000

[Darren Schreiber]

Hi Paul,

You are not "calling out" fro the looks of this log, you are calling another extension on the account. You have assigned the user for this extension to the same user as the extension you are calling to.

The system thinks you are calling yourself. There is usually no reason to call yourself so the system, by default, skips ringing of a device when calling yourself and instead goes to the next call flow action (such as voicemail, where it also sees you calling yourself and assumes you are logging into your mailbox).

This tells me you are calling an extension:

INVITE sip:1...@host.domain.com SIP/2.0

and this tells me you are calling yourself and the system is skipping the device:

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_device:32 (<0.5437.5>) error bridging to device: owner_called_self

This tells me that you haven't programmed the system to do anything AFTER ringing a device (like go to voicemail):

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_exe:337 (<0.5430.5>) continuing to child _

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|cf_exe:340 (<0.5430.5>) wildcard child does not exist, we are lost...

The system was attempting to go to the next step (a "wildcard" I.e. an "anything" after ringing a device) and found nothing, so it gave up. This is akin to "No more dial plan/callflow actions to execute, you haven't set anything else up for us to do!".

The system is behaving correctly and returning the correct response. You need to fix your call flow.

[Paul Kramer]

Okay now I'm a little confused. I've created two separate users and assigned a Cisco and a Mitel phone to each user. I've created callflows for each of the users (105 -> User1 -> Cisco phone, 102 -> User2 -> Mitel phone) and still when dialling extension 105 from the Mitel I'm receiving temporarily unavailable. Then I tried ticking the "allow user to call themselves" checkbox which resulted in the Mitel phone displaying "User2" and not "User1" on the screen when dialling 105.   

[Darren Schreiber]

The device data is cached. Wait 15 minutes OR run

sup wh_cache flush

sup whapps_cache flush

(one of those two anyway, I forget which)

[Paul Kramer]

Beautiful, it's sorted. Thanks for your help Darren

On Thursday, 25 October 2012 09:06:33 UTC+11, Darren Schreiber wrote:

The device data is cached. Wait 15 minutes OR run

sup wh_cache flush

sup whapps_cache flush

(one of those two anyway, I forget which)

--

Darren Schreiber

CEO / Co-Founder

 visit: www.2600hz.com

 sip:dar...@2600hz.com

 tel: 415-886-7901

From: Paul Kramer <paul....@gmail.com>
Reply-To: "2600h...@googlegroups.com" <2600h...@googlegroups.com>
Date: Wednesday, October 24, 2012 2:54 PM
To: "2600h...@googlegroups.com" <2600h...@googlegroups.com>
Subject: Re: 480 Temporarily Unavailable

Okay now I'm a little confused. I've created two separate users and assigned a Cisco and a Mitel phone to each user. I've created callflows for each of the users (105 -> User1 -> Cisco phone, 102 -> User2 -> Mitel phone) and still when dialling extension 105 from the Mitel I'm receiving temporarily unavailable. Then I tried ticking the "allow user to call themselves" checkbox which resulted in the Mitel phone displaying "User2" and not "User1" on the screen when dialling 105.   

On Thu, Oct 25, 2012 at 12:43 AM, Darren Schreiber <dar...@2600hz.com> wrote:

Hi Paul,

You are not "calling out" fro the looks of this log, you are calling another extension on the account. You have assigned the user for this extension to the same user as the extension you are calling to.

The system thinks you are calling yourself. There is usually no reason to call yourself so the system, by default, skips ringing of a device when calling yourself and instead goes to the next call flow action (such as voicemail, where it also sees you calling yourself and assumes you are logging into your mailbox).

This tells me you are calling an extension:

INVITE sip...@host.domain.com SIP/2.0

Oct 24 02:44:12 kazoo 2600hz[12657]: |1db90000...@host.domain.com|gen_listener:551 (<0.5430.5>) terminating binding call ([{callid,<<"1db90000-3f03...@host.domain.com">>}])

Oct 24 02:44:17 kazoo 2600hz[2520]: |1db90000...@host.domain.com|gen_listener:551 (<0.28366.0>) terminating binding call ([{callid,<<"1db90000-3f03...@host.domain.com">>},{restrict_to,[events]}])

Oct 24 02:44:17 kazoo 2600hz[2520]: |1db90000...@host.domain.com|gen_listener:551 (<0.28366.0>) terminating binding dialplan ([])

Oct 24 02:44:17 kazoo 2600hz[2520]: |1db90000...@host.domain.com|gen_listener:551 (<0.28366.0>) terminating binding self ([])

Oct 24 02:44:17 kazoo 2600hz[2520]: |1db90000...@host.domain.com|gen_listener:554 (<0.28366.0>) ecallmgr_call_control terminated cleanly, going down

And the associated invite....

@@&iLuEC4z:28WMuINVITE sip...@host.domain.com SIP/2.0

Via:SIP/2.0/UDP <public_ip>:61557;rport;branch=z9hG4bK1dba0052

From:"5340" <sip:...@host.domain.com>;tag=50871db9-a4-2c6e7c9c

To:<sip...@host.domain.com>

Contact:"5340" <sip:5340@<public_ip>:61557;transport=UDP>

Call-ID:1db9...@host.domain.com

Subject:sip phone call

CSeq:128804807 INVITE

User-Agent:Mitel-5340-SIP-Phone 05.01.00.16 08000F3B50CE

Proxy-Authorization: Digest username="5340", realm="host.domain.com", nonce="dfb8d462-23ef-49b3-a7c4-aca0c27aadd3", uri="sip...@host.domain.com", qop=auth, nc=00000001, cnonce="29-1351032250", response="a7a5c46be39ea48f346ebadb0fcf3ca9", opaque="", algorithm=MD5

Allow:INVITE,ACK,CANCEL,BYE,OPTIONS,REFER,NOTIFY,PRACK,UPDATE

Allow-Events:talk,hold,conference

Supported:timer,100rel,replaces

Session-Expires: 1800;refresher=uas

Min-SE: 90

Max-Forwards:70

Content-Type:application/sdp

Content-Length:278

v=0

o=5340 1351032414 1351032413 IN IP4 <public_ip>

s=SIP Call

i=(o=IN IP4 192.168.10.103)

c=IN IP4 <public_IP>

t=0 0

a=sendrecv

m=audio 15266 RTP/AVP 0 8 18 101

a=rtpmap:0 PCMU/8000

a=rtpmap:8 PCMA/8000

a=rtpmap:18 G729/8000

a=rtpmap:101 telephone-event/8000

On Wed, Oct 24, 2012 at 12:25 PM, Darren Schreiber <dar...@2600hz.com> wrote:

Where is the packet that started this? (the INVITE)?

Also, please do this:

grep "0024142e-31dd000d-19dcb5c1-6346...@192.168.13.100" /var/log/2600hz-platform.log

on your apps servers and post that.

--

Darren Schreiber

CEO / Co-Founder

 visit: www.2600hz.com

 sip:dar...@2600hz.com

 tel: 415-886-7901

From: Paul Kramer <paul....@gmail.com>
Reply-To: "2600h...@googlegroups.com" <2600h...@googlegroups.com>
Date: Tuesday, October 23, 2012 6:24 PM
To: "2600h...@googlegroups.com" <2600h...@googlegroups.com>
Subject: Re: 480 Temporarily Unavailable

Here's the actual SIP message from the Mitel 5340 SIP phone.

SIP/2.0 480 Temporarily Unavailable

Via: SIP/2.0/UDP <IP>:7529;branch=z9hG4bKf5579871

Max-Forwards: 70

From: "105" <sip:ci...@kazoo.com>;tag=0024142e31dd0f0dec725b41-3c9e5d71

To: <sip:1...@kazoo.com>;tag=189p1m7aU6eUB

Call-ID: 0024142e-31dd000d-19dcb5c1-6346...@192.168.13.100

CSeq: 102 INVITE

User-Agent: 2600hz

Accept: application/sdp

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

Supported: precondition, path, replaces

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

Reason: Q.850;cause=16;text="NORMAL_CLEARING"

Content-Length: 0

Remote-Party-ID: "102" <sip:1...@kazoo.com>;party=calling;privacy=off;screen=no

[Darren Schreiber]

Would you mind sharing the settings you used for Cisco & Mitel phones? We're trying to collect those. The more screenshots, the better.

Feel free to email me them off list, I'll put them on the wiki.

[Paul Kramer]

On the Mitel I've just configured the SIP proxy/registrar via the web interface but I can send you my Cisco 7941 config (although very primitive). Maybe it'd be useful to add a phone confguration page to your wiki that can be constantly updated by users?

Paul

[Darren Schreiber]

I am working on exactly that. https://2600hz.atlassian.net/wiki/display/docs/Manual+Provisioning will be split out into model-specific instructions. But need pictures first :)