I've got FusionPBX freshly installed and two Polycom phones set up via auto provisioning. No other settings have been touched and the Polycom 4.x config files are at their defaults. I can make outgoing calls just fine but incoming calls never ring the phones, they go straight to voicemail. Also if I call between phones by extension numbers, same thing, straight to voicemail. In a previous test run of Fusion I did have incoming dialing working but that was before I started over and this time did it with auto provisioning.
My intent is not to post a massive log and have someone else solve my problem. I've read the logs and need help learning what they mean so that I can work with them in the future. In the logs I see it parsing through the Dialplan criteria and then the following. Towards the end seems to be when it starts talking about voicemail but I can't seem to discover what it causing it to make that decision instead of ringing. I have highlighted that in bold, below.
Thank you for your assistance.
IP550 = Extension 501
IP331 = Extension 502
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.264065 [DEBUG] switch_channel.c:1250 sofia/internal/501@192.168.25.5 EXPORTING[export_vars] [dialed_extension]=[502] to event
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.264065 [DEBUG] switch_channel.c:1250 sofia/internal/501@192.168.25.5 EXPORTING[export_vars] [origination_callee_id_name]=[502] to event
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.264065 [DEBUG] switch_channel.c:1250 sofia/internal/501@192.168.25.5 EXPORTING[export_vars] [domain_name]=[192.168.25.5] to event
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.264065 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.264065 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/502@192.168.25.118 [7d0e24ef-c58b-4d05-9900-31dd46cebf83]
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.264065 [DEBUG] mod_sofia.c:4819 (sofia/internal/502@192.168.25.118) State Change CS_NEW -> CS_INIT
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/502@192.168.25.118) Running State Change CS_INIT (Cur 2 Tot 78)
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/502@192.168.25.118) State INIT
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] mod_sofia.c:90 sofia/internal/502@192.168.25.118 SOFIA INIT
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] sofia_glue.c:1295 sofia/internal/502@192.168.25.118 sending invite version: 1.6.19 -36-7a77e0b 64bit
7d0e24ef-c58b-4d05-9900-31dd46cebf83 Local SDP:
7d0e24ef-c58b-4d05-9900-31dd46cebf83 v=0
7d0e24ef-c58b-4d05-9900-31dd46cebf83 o=FreeSWITCH 1504594982 1504594983 IN IP4 192.168.25.5
7d0e24ef-c58b-4d05-9900-31dd46cebf83 s=FreeSWITCH
7d0e24ef-c58b-4d05-9900-31dd46cebf83 c=IN IP4 192.168.25.5
7d0e24ef-c58b-4d05-9900-31dd46cebf83 t=0 0
7d0e24ef-c58b-4d05-9900-31dd46cebf83 m=audio 26848 RTP/AVP 9 0 8 3 101 13
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=rtpmap:9 G722/8000
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=rtpmap:0 PCMU/8000
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=rtpmap:8 PCMA/8000
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=rtpmap:3 GSM/8000
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=rtpmap:101 telephone-event/8000
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=fmtp:101 0-16
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=rtpmap:13 CN/8000
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=ptime:20
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=sendrecv
7d0e24ef-c58b-4d05-9900-31dd46cebf83
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:40 sofia/internal/502@192.168.25.118 Standard INIT
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/502@192.168.25.118) State Change CS_INIT -> CS_ROUTING
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/502@192.168.25.118) State INIT going to sleep
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/502@192.168.25.118) Running State Change CS_ROUTING (Cur 2 Tot 78)
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] sofia.c:7084 Channel sofia/internal/502@192.168.25.118 entering state [calling][0]
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/502@192.168.25.118) State ROUTING
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] mod_sofia.c:143 sofia/internal/502@192.168.25.118 SOFIA ROUTING
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/502@192.168.25.118) State Change CS_ROUTING -> CS_CONSUME_MEDIA
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/502@192.168.25.118) State ROUTING going to sleep
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/502@192.168.25.118) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 78)
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/502@192.168.25.118) State CONSUME_MEDIA
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/502@192.168.25.118) State CONSUME_MEDIA going to sleep
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] sofia.c:7084 Channel sofia/internal/502@192.168.25.118 entering state [terminated][400]
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [NOTICE] sofia.c:8273 Hangup sofia/internal/502@192.168.25.118 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE]
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/502@192.168.25.118) Running State Change CS_HANGUP (Cur 2 Tot 78)
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/502@192.168.25.118) Callstate Change DOWN -> HANGUP
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/502@192.168.25.118) State HANGUP
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] mod_sofia.c:438 Channel sofia/internal/502@192.168.25.118 hanging up, cause: NORMAL_TEMPORARY_FAILURE
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:60 sofia/internal/502@192.168.25.118 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/502@192.168.25.118) State HANGUP going to sleep
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/502@192.168.25.118) State Change CS_HANGUP -> CS_REPORTING
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/502@192.168.25.118) Running State Change CS_REPORTING (Cur 2 Tot 78)
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/502@192.168.25.118) State REPORTING
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:174 sofia/internal/502@192.168.25.118 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/502@192.168.25.118) State REPORTING going to sleep
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/502@192.168.25.118) State Change CS_REPORTING -> CS_DESTROY
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_session.c:1665 Session 78 (sofia/internal/502@192.168.25.118) Locked, Waiting on external entities
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [user] cause: [NORMAL_TEMPORARY_FAILURE]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [INFO] mod_dptools.c:3436 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 lua(app.lua failure_handler)
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_cpp.cpp:1112 sofia/internal/501@192.168.25.5 destroy/unlink session from object
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 answer()
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/internal/501@192.168.25.5] 192.168.25.5 port 19884 -> 192.168.25.136 port 2248 codec: 9 ms: 20
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.304106 [NOTICE] switch_core_session.c:1683 Session 78 (sofia/internal/502@192.168.25.118) Ended
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.304106 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/502@192.168.25.118 [CS_DESTROY]
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.304106 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/502@192.168.25.118) Running State Change CS_DESTROY (Cur 1 Tot 78)
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.304106 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/502@192.168.25.118) State DESTROY
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.304106 [DEBUG] mod_sofia.c:343 sofia/internal/502@192.168.25.118 SOFIA DESTROY
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.304106 [DEBUG] switch_core_state_machine.c:181 sofia/internal/502@192.168.25.118 Standard DESTROY
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.304106 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/502@192.168.25.118) State DESTROY going to sleep
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 160 bytes per 20ms
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_core_media.c:7179 sofia/internal/501@192.168.25.5 Set 2833 dtmf send payload to 127
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_core_media.c:7186 sofia/internal/501@192.168.25.5 Set 2833 dtmf receive payload to 127
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_core_media.c:7209 sofia/internal/501@192.168.25.5 Set rtp dtmf delay to 40
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/501@192.168.25.5:
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 v=0
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 o=FreeSWITCH 1504601946 1504601947 IN IP4 192.168.25.5
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 s=FreeSWITCH
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 c=IN IP4 192.168.25.5
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 t=0 0
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 m=audio 19884 RTP/AVP 9 127
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 a=rtpmap:9 G722/8000
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 a=rtpmap:127 telephone-event/8000
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 a=fmtp:127 0-16
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 a=ptime:20
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 a=sendrecv
13606ec9-0ba0-4783-b912-8f1bc2dbabf5
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] sofia.c:7084 Channel sofia/internal/501@192.168.25.5 entering state [completed][200]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [NOTICE] mod_dptools.c:1312 Channel [sofia/internal/501@192.168.25.5] has been answered
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_channel.c:3773 (sofia/internal/501@192.168.25.5) Callstate Change RINGING -> ACTIVE
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 sleep(1000)
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.324065 [DEBUG] sofia.c:7084 Channel sofia/internal/501@192.168.25.5 entering state [ready][200]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.444066 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed.
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 set(voicemail_action=save)
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.304281 [DEBUG] mod_dptools.c:1548 SET sofia/internal/501@192.168.25.5 [voicemail_action]=[save]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 set(voicemail_id=502)
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.304281 [DEBUG] mod_dptools.c:1548 SET sofia/internal/501@192.168.25.5 [voicemail_id]=[502]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 set(voicemail_profile=default)
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.304281 [DEBUG] mod_dptools.c:1548 SET sofia/internal/501@192.168.25.5 [voicemail_profile]=[default]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 lua(app.lua voicemail)
2017-09-05 10:30:31.304281 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x1137720 Connected.
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 unbind_meta_app()
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.304281 [INFO] switch_ivr_async.c:4072 UnBound A-Leg: ALL
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.304281 [DEBUG] switch_cpp.cpp:745 CoreSession::setVariable(playback_terminators, #)
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 playback(silence_stream://200)
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.304281 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@16000hz 1 channels 20ms
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.504262 [DEBUG] switch_ivr_play_say.c:1942 done playing file silence_stream://200
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.504262 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@16000hz 1 channels 20ms
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:32.444287 [NOTICE] sofia.c:1012 Hangup sofia/internal/501@192.168.25.5 [CS_EXECUTE] [NORMAL_CLEARING]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:32.444287 [DEBUG] mod_hash.c:297 Usage for 192.168.25.5_502 is now 0
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:32.444287 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/share/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav
2017-09-05 10:30:32.444287 [NOTICE] switch_cpp.cpp:1365 [voicemail]
2017-09-05 10:30:32.444287 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x1137720 released.
My intent is not to post a massive log and have someone else solve my problem. I've read the logs and need help learning what they mean so that I can work with them in the future. In the logs I see it parsing through the Dialplan criteria and then the following. Towards the end seems to be when it starts talking about voicemail but I can't seem to discover what it causing it to make that decision instead of ringing. I have highlighted that in bold, below.
Thank you for your assistance.
IP550 = Extension 501
IP331 = Extension 502
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.264065 [DEBUG] switch_channel.c:1250 sofia/internal/501@192.168.25.5 EXPORTING[export_vars] [dialed_extension]=[502] to event
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.264065 [DEBUG] switch_channel.c:1250 sofia/internal/501@192.168.25.5 EXPORTING[export_vars] [origination_callee_id_name]=[502] to event
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.264065 [DEBUG] switch_channel.c:1250 sofia/internal/501@192.168.25.5 EXPORTING[export_vars] [domain_name]=[192.168.25.5] to event
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.264065 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.264065 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/502@192.168.25.118 [7d0e24ef-c58b-4d05-9900-31dd46cebf83]
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.264065 [DEBUG] mod_sofia.c:4819 (sofia/internal/502@192.168.25.118) State Change CS_NEW -> CS_INIT
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/502@192.168.25.118) Running State Change CS_INIT (Cur 2 Tot 78)
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/502@192.168.25.118) State INIT
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] mod_sofia.c:90 sofia/internal/502@192.168.25.118 SOFIA INIT
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] sofia_glue.c:1295 sofia/internal/502@192.168.25.118 sending invite version: 1.6.19 -36-7a77e0b 64bit
7d0e24ef-c58b-4d05-9900-31dd46cebf83 Local SDP:
7d0e24ef-c58b-4d05-9900-31dd46cebf83 v=0
7d0e24ef-c58b-4d05-9900-31dd46cebf83 o=FreeSWITCH 1504594982 1504594983 IN IP4 192.168.25.5
7d0e24ef-c58b-4d05-9900-31dd46cebf83 s=FreeSWITCH
7d0e24ef-c58b-4d05-9900-31dd46cebf83 c=IN IP4 192.168.25.5
7d0e24ef-c58b-4d05-9900-31dd46cebf83 t=0 0
7d0e24ef-c58b-4d05-9900-31dd46cebf83 m=audio 26848 RTP/AVP 9 0 8 3 101 13
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=rtpmap:9 G722/8000
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=rtpmap:0 PCMU/8000
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=rtpmap:8 PCMA/8000
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=rtpmap:3 GSM/8000
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=rtpmap:101 telephone-event/8000
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=fmtp:101 0-16
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=rtpmap:13 CN/8000
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=ptime:20
7d0e24ef-c58b-4d05-9900-31dd46cebf83 a=sendrecv
7d0e24ef-c58b-4d05-9900-31dd46cebf83
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:40 sofia/internal/502@192.168.25.118 Standard INIT
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/502@192.168.25.118) State Change CS_INIT -> CS_ROUTING
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/502@192.168.25.118) State INIT going to sleep
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/502@192.168.25.118) Running State Change CS_ROUTING (Cur 2 Tot 78)
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] sofia.c:7084 Channel sofia/internal/502@192.168.25.118 entering state [calling][0]
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/502@192.168.25.118) State ROUTING
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] mod_sofia.c:143 sofia/internal/502@192.168.25.118 SOFIA ROUTING
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/502@192.168.25.118) State Change CS_ROUTING -> CS_CONSUME_MEDIA
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/502@192.168.25.118) State ROUTING going to sleep
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/502@192.168.25.118) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 78)
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/502@192.168.25.118) State CONSUME_MEDIA
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/502@192.168.25.118) State CONSUME_MEDIA going to sleep
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] sofia.c:7084 Channel sofia/internal/502@192.168.25.118 entering state [terminated][400]
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [NOTICE] sofia.c:8273 Hangup sofia/internal/502@192.168.25.118 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE]
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/502@192.168.25.118) Running State Change CS_HANGUP (Cur 2 Tot 78)
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/502@192.168.25.118) Callstate Change DOWN -> HANGUP
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/502@192.168.25.118) State HANGUP
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] mod_sofia.c:438 Channel sofia/internal/502@192.168.25.118 hanging up, cause: NORMAL_TEMPORARY_FAILURE
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:60 sofia/internal/502@192.168.25.118 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/502@192.168.25.118) State HANGUP going to sleep
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/502@192.168.25.118) State Change CS_HANGUP -> CS_REPORTING
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/502@192.168.25.118) Running State Change CS_REPORTING (Cur 2 Tot 78)
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/502@192.168.25.118) State REPORTING
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:174 sofia/internal/502@192.168.25.118 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/502@192.168.25.118) State REPORTING going to sleep
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/502@192.168.25.118) State Change CS_REPORTING -> CS_DESTROY
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.284074 [DEBUG] switch_core_session.c:1665 Session 78 (sofia/internal/502@192.168.25.118) Locked, Waiting on external entities
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [user] cause: [NORMAL_TEMPORARY_FAILURE]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [INFO] mod_dptools.c:3436 Originate Failed. Cause: NORMAL_TEMPORARY_FAILURE
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 lua(app.lua failure_handler)
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_cpp.cpp:1112 sofia/internal/501@192.168.25.5 destroy/unlink session from object
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 answer()
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/internal/501@192.168.25.5] 192.168.25.5 port 19884 -> 192.168.25.136 port 2248 codec: 9 ms: 20
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.304106 [NOTICE] switch_core_session.c:1683 Session 78 (sofia/internal/502@192.168.25.118) Ended
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.304106 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/502@192.168.25.118 [CS_DESTROY]
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.304106 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/502@192.168.25.118) Running State Change CS_DESTROY (Cur 1 Tot 78)
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.304106 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/502@192.168.25.118) State DESTROY
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.304106 [DEBUG] mod_sofia.c:343 sofia/internal/502@192.168.25.118 SOFIA DESTROY
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.304106 [DEBUG] switch_core_state_machine.c:181 sofia/internal/502@192.168.25.118 Standard DESTROY
7d0e24ef-c58b-4d05-9900-31dd46cebf83 2017-09-05 10:30:30.304106 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/502@192.168.25.118) State DESTROY going to sleep
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_rtp.c:4111 Starting timer [soft] 160 bytes per 20ms
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_core_media.c:7179 sofia/internal/501@192.168.25.5 Set 2833 dtmf send payload to 127
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_core_media.c:7186 sofia/internal/501@192.168.25.5 Set 2833 dtmf receive payload to 127
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_core_media.c:7209 sofia/internal/501@192.168.25.5 Set rtp dtmf delay to 40
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/501@192.168.25.5:
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 v=0
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 o=FreeSWITCH 1504601946 1504601947 IN IP4 192.168.25.5
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 s=FreeSWITCH
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 c=IN IP4 192.168.25.5
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 t=0 0
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 m=audio 19884 RTP/AVP 9 127
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 a=rtpmap:9 G722/8000
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 a=rtpmap:127 telephone-event/8000
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 a=fmtp:127 0-16
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 a=ptime:20
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 a=sendrecv
13606ec9-0ba0-4783-b912-8f1bc2dbabf5
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] sofia.c:7084 Channel sofia/internal/501@192.168.25.5 entering state [completed][200]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [NOTICE] mod_dptools.c:1312 Channel [sofia/internal/501@192.168.25.5] has been answered
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.304106 [DEBUG] switch_channel.c:3773 (sofia/internal/501@192.168.25.5) Callstate Change RINGING -> ACTIVE
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 sleep(1000)
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.324065 [DEBUG] sofia.c:7084 Channel sofia/internal/501@192.168.25.5 entering state [ready][200]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:30.444066 [DEBUG] switch_rtp.c:7271 Correct audio ip/port confirmed.
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 set(voicemail_action=save)
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.304281 [DEBUG] mod_dptools.c:1548 SET sofia/internal/501@192.168.25.5 [voicemail_action]=[save]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 set(voicemail_id=502)
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.304281 [DEBUG] mod_dptools.c:1548 SET sofia/internal/501@192.168.25.5 [voicemail_id]=[502]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 set(voicemail_profile=default)
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.304281 [DEBUG] mod_dptools.c:1548 SET sofia/internal/501@192.168.25.5 [voicemail_profile]=[default]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 lua(app.lua voicemail)
2017-09-05 10:30:31.304281 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x1137720 Connected.
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 unbind_meta_app()
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.304281 [INFO] switch_ivr_async.c:4072 UnBound A-Leg: ALL
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.304281 [DEBUG] switch_cpp.cpp:745 CoreSession::setVariable(playback_terminators, #)
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 EXECUTE sofia/internal/501@192.168.25.5 playback(silence_stream://200)
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.304281 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@16000hz 1 channels 20ms
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.504262 [DEBUG] switch_ivr_play_say.c:1942 done playing file silence_stream://200
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:31.504262 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@16000hz 1 channels 20ms
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:32.444287 [NOTICE] sofia.c:1012 Hangup sofia/internal/501@192.168.25.5 [CS_EXECUTE] [NORMAL_CLEARING]
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:32.444287 [DEBUG] mod_hash.c:297 Usage for 192.168.25.5_502 is now 0
13606ec9-0ba0-4783-b912-8f1bc2dbabf5 2017-09-05 10:30:32.444287 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/share/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav
2017-09-05 10:30:32.444287 [NOTICE] switch_cpp.cpp:1365 [voicemail]
2017-09-05 10:30:32.444287 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x1137720 released.