[Freeswitch-users] Held calls are terminated after ~25 seconds

Thu Jan 14 20:20:53 MSK 2016

I am using two Cisco SPA303 phones with a local FreeSwitch server. Incoming
calls through Plivo dial a group ring extension and everything works as
expected; however, after placing a call on hold the call is terminated
after about 25 seconds. Previously I was getting a warning about the
RFC2543 hold method, and Async PTIME not supported.

I set the SPA303 config setting "RFC2543 Call Hold" from yes to no, and
also added <param name="rtp-autofix-timing" value="false"/> to my
internal.xml sip profile. The errors went away but the issue persists.

Here is the log:

f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:06:40.908307
[DEBUG] switch_channel.c:1831 (sofia/internal/1001 at 192.168.0.114:5060)
Callstate Change ACTIVE -> HELD
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:06:41.158321
[DEBUG] switch_core_media.c:4153 Audio Codec Compare
[PCMU:0:8000:30:64000:1]/[PCMU:0:8000:30:64000:1]
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:06:41.158321
[DEBUG] switch_core_media.c:4208 Audio Codec Compare
[PCMU:0:8000:30:64000:1] ++++ is saved as a match
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:06:41.158321
[DEBUG] switch_core_media.c:4153 Audio Codec Compare
[PCMA:8:8000:30:64000:1]/[PCMU:0:8000:30:64000:1]
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:06:41.158321
[DEBUG] switch_core_media.c:4069 Set telephone-event payload to
101 at 8000
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:06:41.158321
[DEBUG] switch_core_media.c:4417 Set telephone-event payload to
101 at 8000
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:06:41.158321
[DEBUG] switch_core_media.c:4473
sofia/internal/1001 at 192.168.0.114:5060 Set 2833 dtmf send payload to
101 recv payload to 101
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:06:41.158321
[DEBUG] switch_core_media.c:6010 Audio params are unchanged for
sofia/internal/1001 at 192.168.0.114:5060.
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:06:41.158321
[DEBUG] sofia.c:7503 Processing updated SDP
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:06:41.168322
[DEBUG] sofia.c:6756 Channel sofia/internal/1001 at 192.168.0.114:5060
entering state [completed][200]
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:06:41.178318
[DEBUG] sofia.c:6756 Channel sofia/internal/1001 at 192.168.0.114:5060
entering state [ready][200]
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.288104
[DEBUG] sofia.c:6756 Channel
sofia/internal/+14196680795 at 184.106.123.160 entering state
[terminating][0]
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.288104
[NOTICE] sofia.c:7775 Hangup
sofia/internal/+14196680795 at 184.106.123.160 [CS_EXECUTE]
[NORMAL_UNSPECIFIED]
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.288104
[DEBUG] switch_ivr_bridge.c:705
sofia/internal/+14196680795 at 184.106.123.160 ending bridge by request
from read function
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.288104
[DEBUG] switch_ivr_bridge.c:778 BRIDGE THREAD DONE
[sofia/internal/+14196680795 at 184.106.123.160]
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.318106
[DEBUG] switch_ivr_bridge.c:778 BRIDGE THREAD DONE
[sofia/internal/1001 at 192.168.0.114:5060]
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.318106
[DEBUG] switch_channel.c:2019 (sofia/internal/1001 at 192.168.0.114:5060)
Callstate Change HELD -> UNHELD
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.318106
[NOTICE] switch_ivr_bridge.c:881 Hangup
sofia/internal/1001 at 192.168.0.114:5060 [CS_EXCHANGE_MEDIA]
[NORMAL_CLEARING]
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.318106
[DEBUG] switch_core_state_machine.c:542
(sofia/internal/1001 at 192.168.0.114:5060) State EXCHANGE_MEDIA going to
sleep
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.318106
[DEBUG] switch_core_state_machine.c:473
(sofia/internal/1001 at 192.168.0.114:5060) Running State Change
CS_HANGUP
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.318106
[DEBUG] switch_core_state_machine.c:739
(sofia/internal/1001 at 192.168.0.114:5060) Callstate Change UNHELD ->
HANGUP
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.318106
[DEBUG] switch_core_state_machine.c:741
(sofia/internal/1001 at 192.168.0.114:5060) State HANGUP
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.318106
[DEBUG] mod_sofia.c:431 Channel sofia/internal/1001 at 192.168.0.114:5060
hanging up, cause: NORMAL_CLEARING
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.318106
[DEBUG] switch_ivr_bridge.c:1689
sofia/internal/1001 at 192.168.0.114:5060 skip receive message [UNBRIDGE]
(channel is hungup already)
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.318106
[DEBUG] switch_ivr_bridge.c:1692
sofia/internal/+14196680795 at 184.106.123.160 skip receive message
[UNBRIDGE] (channel is hungup already)
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.318106
[DEBUG] switch_core_session.c:2796
sofia/internal/+14196680795 at 184.106.123.160 skip receive message
[APPLICATION_EXEC_COMPLETE] (channel is hungup already)
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.318106
[DEBUG] switch_core_state_machine.c:539
(sofia/internal/+14196680795 at 184.106.123.160) State EXECUTE going to
sleep
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.318106
[DEBUG] switch_core_state_machine.c:473
(sofia/internal/+14196680795 at 184.106.123.160) Running State Change
CS_HANGUP
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.318106
[DEBUG] switch_core_state_machine.c:739
(sofia/internal/+14196680795 at 184.106.123.160) Callstate Change ACTIVE
-> HANGUP
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.318106
[DEBUG] switch_core_state_machine.c:741
(sofia/internal/+14196680795 at 184.106.123.160) State HANGUP
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.318106
[DEBUG] mod_sofia.c:431 Channel
sofia/internal/+14196680795 at 184.106.123.160 hanging up, cause:
NORMAL_UNSPECIFIED
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.328100
[DEBUG] mod_sofia.c:484 Sending BYE to
sofia/internal/1001 at 192.168.0.114:5060
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[DEBUG] switch_core_state_machine.c:60
sofia/internal/1001 at 192.168.0.114:5060 Standard HANGUP, cause:
NORMAL_CLEARING
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[DEBUG] switch_core_state_machine.c:741
(sofia/internal/1001 at 192.168.0.114:5060) State HANGUP going to sleep
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[DEBUG] switch_core_state_machine.c:508
(sofia/internal/1001 at 192.168.0.114:5060) State Change CS_HANGUP ->
CS_REPORTING
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[DEBUG] switch_core_state_machine.c:473
(sofia/internal/1001 at 192.168.0.114:5060) Running State Change
CS_REPORTING
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[DEBUG] switch_core_state_machine.c:827
(sofia/internal/1001 at 192.168.0.114:5060) State REPORTING
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[DEBUG] switch_core_state_machine.c:104
sofia/internal/1001 at 192.168.0.114:5060 Standard REPORTING, cause:
NORMAL_CLEARING
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[DEBUG] switch_core_state_machine.c:827
(sofia/internal/1001 at 192.168.0.114:5060) State REPORTING going to
sleep
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[DEBUG] switch_core_state_machine.c:499
(sofia/internal/1001 at 192.168.0.114:5060) State Change CS_REPORTING ->
CS_DESTROY
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[DEBUG] switch_core_session.c:1646 Session 3
(sofia/internal/1001 at 192.168.0.114:5060) Locked, Waiting on external
entities
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[NOTICE] switch_core_session.c:1664 Session 3
(sofia/internal/1001 at 192.168.0.114:5060) Ended
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[NOTICE] switch_core_session.c:1668 Close Channel
sofia/internal/1001 at 192.168.0.114:5060 [CS_DESTROY]
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[DEBUG] switch_core_state_machine.c:630
(sofia/internal/1001 at 192.168.0.114:5060) Running State Change
CS_DESTROY
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[DEBUG] switch_core_state_machine.c:640
(sofia/internal/1001 at 192.168.0.114:5060) State DESTROY
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[DEBUG] mod_sofia.c:341 sofia/internal/1001 at 192.168.0.114:5060 SOFIA
DESTROY
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[DEBUG] switch_core_state_machine.c:111
sofia/internal/1001 at 192.168.0.114:5060 Standard DESTROY
f9765406-acd9-480c-a200-43bdc2ad2f36 2016-01-14 12:07:12.338101
[DEBUG] switch_core_state_machine.c:640
(sofia/internal/1001 at 192.168.0.114:5060) State DESTROY going to sleep
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.348102
[DEBUG] switch_core_state_machine.c:60
sofia/internal/+14196680795 at 184.106.123.160 Standard HANGUP, cause:
NORMAL_UNSPECIFIED
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.348102
[DEBUG] switch_core_state_machine.c:741
(sofia/internal/+14196680795 at 184.106.123.160) State HANGUP going to
sleep
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.348102
[DEBUG] switch_core_state_machine.c:508
(sofia/internal/+14196680795 at 184.106.123.160) State Change CS_HANGUP
-> CS_REPORTING
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.348102
[DEBUG] switch_core_state_machine.c:473
(sofia/internal/+14196680795 at 184.106.123.160) Running State Change
CS_REPORTING
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.348102
[DEBUG] switch_core_state_machine.c:827
(sofia/internal/+14196680795 at 184.106.123.160) State REPORTING
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.348102
[DEBUG] switch_core_state_machine.c:104
sofia/internal/+14196680795 at 184.106.123.160 Standard REPORTING, cause:
NORMAL_UNSPECIFIED
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.348102
[DEBUG] switch_core_state_machine.c:827
(sofia/internal/+14196680795 at 184.106.123.160) State REPORTING going to
sleep
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.348102
[DEBUG] switch_core_state_machine.c:499
(sofia/internal/+14196680795 at 184.106.123.160) State Change
CS_REPORTING -> CS_DESTROY
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.348102
[DEBUG] switch_core_session.c:1646 Session 1
(sofia/internal/+14196680795 at 184.106.123.160) Locked, Waiting on
external entities
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.348102
[NOTICE] switch_core_session.c:1664 Session 1
(sofia/internal/+14196680795 at 184.106.123.160) Ended
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.348102
[NOTICE] switch_core_session.c:1668 Close Channel
sofia/internal/+14196680795 at 184.106.123.160 [CS_DESTROY]
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.358102
[DEBUG] switch_core_state_machine.c:630
(sofia/internal/+14196680795 at 184.106.123.160) Running State Change
CS_DESTROY
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.358102
[DEBUG] switch_core_state_machine.c:640
(sofia/internal/+14196680795 at 184.106.123.160) State DESTROY
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.358102
[DEBUG] mod_sofia.c:341 sofia/internal/+14196680795 at 184.106.123.160
SOFIA DESTROY
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.358102
[DEBUG] switch_core_state_machine.c:111
sofia/internal/+14196680795 at 184.106.123.160 Standard DESTROY
9cbfdabc-8f1f-4fb3-89f2-c1b0c8522c5c 2016-01-14 12:07:12.358102
[DEBUG] switch_core_state_machine.c:640
(sofia/internal/+14196680795 at 184.106.123.160) State DESTROY going to
sleep
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20160114/13626413/attachment-0001.html 