SCCP Cisco Phone 7937 - Disconnecting in the middle of outbound calls

alykov · September 23, 2019, 10:45pm

Hello,

I’ve got Sangoma/FreePBX 14.0.13.4 with SIP trunk, bunch SIP phones (they are fine) and one dodgy SCCP cisco 7937 Conference phone. This phone hung up on outbound calls sometimes in 1-2min after start or sometimes it could be up to 10min online.
Also, if pressed the Mute button on it, it’s doing the same almost immediately. What also I should debug to find out why?
Thanks,
Alex.

---- SCCP Logs ----

>  [2019-09-23 14:55:46] VERBOSE[74426][C-00000004] bridge_channel.c: Channel PJSIP/Spark-0000000b left 'simple_bridge' basic-bridge <7130390f-f04a-4af9-974a-517c019c70b0>
>  [2019-09-23 14:55:46] VERBOSE[74419][C-00000004] bridge_channel.c: Channel SCCP/200-00000005 left 'simple_bridge' basic-bridge <7130390f-f04a-4af9-974a-517c019c70b0>
>  [2019-09-23 14:55:46] NOTICE[74419][C-00000004] ast115.c:     -- SCCP: (pbx_indicate) start indicate 'AST_CONTROL_SRCCHANGE: Media source has changed and requires a new RTP SSRC'
>  [2019-09-23 14:55:46] VERBOSE[74419][C-00000004] sccp_refcount.c:  ast115.c       :0571 (sccp_wrapper_asterisk115_indicate  ) --->                   refcount increased 03  +> 04 for    channel: SCCP/200-00000005 (0x7f4a80005970)
> [2019-09-23 14:55:46] VERBOSE[74419][C-00000004] sccp_refcount.c:  sccp_channel.c :0231 (sccp_channel_getDevice             ) ---->                  refcount increased 04  +> 05 for     device: SEP0004F2EDD094 (0x2bc84a0)
>     [2019-09-23 14:55:46] NOTICE[74419][C-00000004] ast115.c:     -- SEP0004F2EDD094: (pbx_indicate) start indicate 'AST_CONTROL_SRCCHANGE: Media source has changed and requires a new RTP SSRC' (26)
>      condition on channel SCCP/200-00000005 (readStat:2, receiveChannelState:2, rtp:yes, default res:inband signaling (-1))
>     [2019-09-23 14:55:46] NOTICE[74419][C-00000004] ast115.c:   == SEP0004F2EDD094: (pbx_indicate) finish: send indication 'outofband signaling' (0)
>     [2019-09-23 14:55:46] VERBOSE[74419][C-00000004] sccp_refcount.c:  ast115.c       :0577 (sccp_wrapper_asterisk115_indicate  ) <----                  refcount decreased 04  <- 05 for     device: SEP0004F2EDD094 (0x2bc84a0)
>     [2019-09-23 14:55:46] VERBOSE[74419][C-00000004] sccp_refcount.c:  ast115.c       :0571 (sccp_wrapper_asterisk115_indicate  ) <---                   refcount decreased 03  <- 04 for    channel: SCCP/200-00000005 (0x7f4a80005970)
>     [2019-09-23 14:55:46] VERBOSE[74419][C-00000004] app_macro.c: Spawn extension (macro-dialout-trunk, s, 23) exited non-zero on 'SCCP/200-00000005' in macro 'dialout-trunk'
>     [2019-09-23 14:55:46] VERBOSE[74419][C-00000004] pbx.c: Spawn extension (from-internal-xfer, 0220110284, 7) exited non-zero on 'SCCP/200-00000005'
>     [2019-09-23 14:55:46] VERBOSE[74419][C-00000004] pbx.c: Executing [h@from-internal-xfer:1] Macro("SCCP/200-00000005", "hangupcall") in new stack
>     [2019-09-23 14:55:46] VERBOSE[74419][C-00000004] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SCCP/200-00000005", "1?theend") in new stack

[…]

------ Cisco Phone Logs --------

[09-23]16:41:24.778|sccp |3|00|runRegistrationManager: restartFindFailBack_RegManagerMsgID cm[0] param2=0
[09-23]16:41:24.778|sccp |3|00|registrationEvent_RegistrationManager: REGISTERED(EVENT_RESTART_FIND_FAILBACK) param1=0 param2=0
[09-23]16:41:24.778|sccp |3|00|findFailBackCallManager: startCallManager=0 endCallManager=6
[09-23]16:41:24.779|sccp |3|00|findFailBackCallManager: failBackCallManager=0
[09-23]16:41:24.779|sccp |3|00|findFailBackCallManager: connect to failBackCallManager=0
[09-23]16:41:24.779|sccp |3|00|findFailBackCallManager: failBackCallManager=0
[09-23]16:41:24.779|sccp |3|00|connectCallManager: connect to CM0 type=SERVER_LIST
[09-23]16:41:24.779|sccp |4|00|registrationEvent_StationRegistration: ERROR connectCallManager cm0 failed
[09-23]16:41:24.780|sccp |3|00|runRegistrationManager: lastConnectFailed_RegManagerMsgID cm[0] param2=0
[09-23]16:41:24.780|sccp |3|00|registrationEvent_RegistrationManager: REGISTERED(EVENT_LAST_CONNECT_FAILED) param1=0 param2=0
[09-23]16:41:24.780|sccp |3|00|findFailBackCallManager: startCallManager=1 endCallManager=1
[09-23]16:41:24.780|sccp |3|00|findFailBackCallManager: startCallManager=1 less than endCallManager=1
[09-23]16:41:24.781|sccp |3|00|findFailBackCallManager: failBackCallManager=6
[09-23]16:41:24.781|sccp |3|00|registered_RegistrationManager: kick off timer to retry failBack
[09-23]16:41:34.946|sccp |3|00|Received --- StationStartToneMessage tone=32
[09-23]16:41:34.963|sccp |3|00|Received --- StationStopMediaTransmissionMessage
[09-23]16:41:35.025|sccp |3|00|processStopMediaTransmissionMsg: stopping transmission
[09-23]16:41:35.040|sccp |3|00|Received --- StationCloseReceiveChannelMessage callReference=1
[09-23]16:41:35.099|sccp |3|00|Received --- StationStopToneMessage
[09-23]16:41:35.119|sccp |3|00|Received --- StationSetLampMessage
[09-23]16:41:35.139|sccp |3|00|Received --- StationClearPromptStatusMessage line=1 callReference=1
[09-23]16:41:35.139|ui   |4|00|processClearPromptStatusSig: ERROR uiDisplayTextClearItem failed
[09-23]16:41:35.159|sccp |3|00|Received --- StationCallStateMessage LineNum=1 CallRef=1 CallState=2
[09-23]16:41:35.159|sccp |3|00|freeSkinnyCall_SkinnyCall: callPtr=4090cf60 callRef=1
[09-23]16:41:35.160|sccp |3|00|sccpCallStateInfoChangeCallBack: callCount=0
[09-23]16:41:35.160|sccp |3|00|sccpCallStateInfoChangeCallBack: callCount=0
[09-23]16:41:35.160|sccp |3|00|sccpCallStateInfoChangeCallBack: callCount=0
[09-23]16:41:35.160|sccp |3|00|sccpCallStateInfoChangeCallBack: callCount=0
[09-23]16:41:35.180|sccp |3|00|runRegistrationManager: endCall_RegManagerMsgID cm[0] param2=0
[09-23]16:41:35.180|sccp |3|00|registrationEvent_RegistrationManager: REGISTERED(EVENT_CALL_CLEARED) param1=0 param2=0
[09-23]16:41:35.181|sccp |3|00|registered_RegistrationManager: unhandled event REGISTERED(EVENT_CALL_CLEARED)
[09-23]16:41:35.181|sccp |3|00|runRegistrationManager: endCall_RegManagerMsgID cm[0] param2=0
[09-23]16:41:35.181|sccp |3|00|registrationEvent_RegistrationManager: REGISTERED(EVENT_CALL_CLEARED) param1=0 param2=0
[09-23]16:41:35.181|sccp |3|00|registered_RegistrationManager: unhandled event REGISTERED(EVENT_CALL_CLEARED)
[09-23]16:41:35.181|sccp |3|00|runRegistrationManager: endCall_RegManagerMsgID cm[0] param2=0
[09-23]16:41:35.182|sccp |3|00|registrationEvent_RegistrationManager: REGISTERED(EVENT_CALL_CLEARED) param1=0 param2=0
[09-23]16:41:35.182|sccp |3|00|registered_RegistrationManager: unhandled event REGISTERED(EVENT_CALL_CLEARED)
[09-23]16:41:35.182|sccp |3|00|runRegistrationManager: endCall_RegManagerMsgID cm[0] param2=0
[09-23]16:41:35.182|sccp |3|00|registrationEvent_RegistrationManager: REGISTERED(EVENT_CALL_CLEARED) param1=0 param2=0
[09-23]16:41:35.182|sccp |3|00|registered_RegistrationManager: unhandled event REGISTERED(EVENT_CALL_CLEARED)
[09-23]16:41:35.204|sccp |3|00|Received --- StationSelectSoftKeysMessage lineNum=0 callRef=0 softkeyindex=0 mask=-1
[09-23]16:41:35.242|sccp |3|00|Received --- StationDefineTimeDateMessage
[09-23]16:41:35.242|sccp |3|00|setStationTimeDate_SkinnyEngine: SCCP set to New time: 1569256894
[09-23]16:41:35.242|sccp |3|00|setStationTimeDate_SkinnyEngine: Year 119 Mon 8 mday 23 hour 16 min 41 sec 34 yday 265 wday 1
[09-23]16:41:34.242|sccp |3|00|registrationEvent_StationRegistration: cm1 unhandled REGISTERED(TIME_DATE_RES)
[09-23]16:41:34.258|sccp |3|00|Received --- StationSetSpeakerModeMessage
[09-23]16:41:34.278|sccp |3|00|Received --- StationSetRingerMessage: mode=1 duration=1 line=1
[09-23]16:41:34.278|sccp |3|00|sccpCallStateInfoChangeCallBack: callCount=0
[09-23]16:41:34.279|sccp |3|00|runRegistrationManager: endCall_RegManagerMsgID cm[0] param2=0
[09-23]16:41:34.279|sccp |3|00|registrationEvent_RegistrationManager: REGISTERED(EVENT_CALL_CLEARED) param1=0 param2=0
[09-23]16:41:34.279|sccp |3|00|registered_RegistrationManager: unhandled event REGISTERED(EVENT_CALL_CLEARED)
[09-23]16:41:34.298|sccp |4|00|Received --- StationConnectionStatisticsReqMessage messageID=107
[09-23]16:41:34.318|sccp |3|00|Received --- StationClearPromptStatusMessage line=0 callReference=0
[09-23]16:41:34.339|sccp |3|00|Received --- StationDisplayPromptStatusMessageV2 "" timeOut=0 line=0 callReference=0
[09-23]16:41:34.359|sccp |3|00|Received --- StationSelectSoftKeysMessage lineNum=0 callRef=0 softkeyindex=0 mask=-1

Stewart1 · September 23, 2019, 11:14pm

I’m guessing that VAD (Voice Activity Detection, A.K.A silence suppression) is active, so when the source is silent, RTP stops and (after a timeout) Asterisk drops the call.

Make sure that the phone has ‘no vad’ specified for any connection to Asterisk.

If you still have trouble, check the Asterisk logs for RTP timeout.

alykov · September 24, 2019, 8:59pm

Looks like you right, it was silencesuppression turned on on the extension.
Mute is working, and I’m testing if there are still any hangups on calls.
Thanks,
Alex.

system · October 1, 2019, 8:59pm

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.