I recently created a new tenant. This tenant is using GS GXP2170 phones (I typically use yealink). The latest firmware v1.0.11.71 is also installed.
Inbound and outbound calls are working fine. Calls from the GS phone to the PSTN or another extension are able to place the call on hold and resume. Calls from the PSTN to a GS phone cannot be placed on hold. The PSTN is immediately dropped and the GS appears to be on hold. Upon resuming the call clears on the GS. For testing purposes I connected a soft client and yealink to the same tenant and hold/resume works as expected. Has anyone run into this before?
The logs during a failed hold look like this:
Inbound and outbound calls are working fine. Calls from the GS phone to the PSTN or another extension are able to place the call on hold and resume. Calls from the PSTN to a GS phone cannot be placed on hold. The PSTN is immediately dropped and the GS appears to be on hold. Upon resuming the call clears on the GS. For testing purposes I connected a soft client and yealink to the same tenant and hold/resume works as expected. Has anyone run into this before?
The logs during a failed hold look like this:
Code:
2023-04-26 00:47:30.288325 96.07% [DEBUG] switch_channel.c:1975 (sofia/internal/8004@192.168.210.14:25491) Callstate Change ACTIVE -> HELD
2023-04-26 00:47:30.448325 96.07% [DEBUG] switch_ivr.c:632 sofia/internal/+18885551212@<ITSP> Command Execute [depth=0] playback(local_stream://default)
EXECUTE [depth=0] sofia/internal/+18885551212@<ITSP> playback(local_stream://default)
2023-04-26 00:47:30.448325 96.07% [DEBUG] mod_local_stream.c:911 Opening Stream [default/8000] 8000hz
2023-04-26 00:47:30.448325 96.07% [DEBUG] switch_ivr_play_say.c:1556 Codec Activated L16@8000hz 1 channels 20ms
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AES_CM_128_HMAC_SHA1_80]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:]
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:1844 Found suite AES_CM_128_HMAC_SHA1_80
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:1855 Existing key is still valid.
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:5566 Set telephone-event payload to 101@8000
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:5915 Set telephone-event payload to 101@8000
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:5973 sofia/internal/8004@192.168.210.14:25491 Set 2833 dtmf send payload to 101 recv payload to 101
2023-04-26 00:47:30.528337 96.07% [DEBUG] switch_core_media.c:8759 Audio params are unchanged for sofia/internal/8004@192.168.210.14:25491.
2023-04-26 00:47:30.528337 96.07% [DEBUG] sofia.c:8454 Processing updated SDP
2023-04-26 00:47:30.548323 96.07% [DEBUG] sofia.c:7499 Channel sofia/internal/8004@192.168.210.14:25491 entering state [completed][200]
2023-04-26 00:47:30.588318 96.07% [DEBUG] sofia.c:7499 Channel sofia/internal/8004@192.168.210.14:25491 entering state [ready][200]
2023-04-26 00:47:30.668325 96.07% [DEBUG] switch_channel.c:2160 (sofia/internal/8004@192.168.210.14:25491) Callstate Change HELD -> UNHELD
2023-04-26 00:47:30.668325 96.07% [NOTICE] sofia.c:1065 Hangup sofia/internal/8004@192.168.210.14:25491 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2023-04-26 00:47:30.668325 96.07% [DEBUG] switch_ivr_bridge.c:912 BRIDGE THREAD DONE [sofia/internal/8004@192.168.210.14:25491]
2023-04-26 00:47:30.668325 96.07% [NOTICE] switch_ivr_bridge.c:927 Hangup sofia/internal/+18885551212@<ITSP> [CS_EXECUTE] [NORMAL_CLEARING]
2023-04-26 00:47:30.668325 96.07% [DEBUG] mod_hash.c:293 Usage for <FUSION_FQDN>_8004 is now 0
2023-04-26 00:47:30.668325 96.07% [DEBUG] switch_core_state_machine.c:650 (sofia/internal/8004@192.168.210.14:25491) State EXCHANGE_MEDIA going to sleep
2023-04-26 00:47:30.668325 96.07% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/8004@192.168.210.14:25491) Running State Change CS_HANGUP (Cur 2 Tot 396932)
2023-04-26 00:47:30.668325 96.07% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/8004@192.168.210.14:25491) Callstate Change UNHELD -> HANGUP
2023-04-26 00:47:30.668325 96.07% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/8004@192.168.210.14:25491) State HANGUP
2023-04-26 00:47:30.668325 96.07% [DEBUG] mod_sofia.c:468 Channel sofia/internal/8004@192.168.210.14:25491 hanging up, cause: NORMAL_CLEARING
2023-04-26 00:47:30.668325 96.07% [DEBUG] switch_core_state_machine.c:59 sofia/internal/8004@192.168.210.14:25491 Standard HANGUP, cause: NORMAL_CLEARING
2023-04-26 00:47:30.668325 96.07% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/8004@192.168.210.14:25491) State HANGUP going to sleep
2023-04-26 00:47:30.668325 96.07% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/8004@192.168.210.14:25491) State Change CS_HANGUP -> CS_REPORTING
2023-04-26 00:47:30.668325 96.07% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/8004@192.168.210.14:25491) Running State Change CS_REPORTING (Cur 2 Tot 396932)
2023-04-26 00:47:30.688329 96.07% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/8004@192.168.210.14:25491) State REPORTING
2023-04-26 00:47:30.688329 96.07% [DEBUG] switch_core_state_machine.c:168 sofia/internal/8004@192.168.210.14:25491 Standard REPORTING, cause: NORMAL_CLEARING
2023-04-26 00:47:30.688329 96.07% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/8004@192.168.210.14:25491) State REPORTING going to sleep
2023-04-26 00:47:30.688329 96.07% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/8004@192.168.210.14:25491) State Change CS_REPORTING -> CS_DESTROY
2023-04-26 00:47:30.688329 96.07% [DEBUG] switch_core_session.c:1753 Session 396932 (sofia/internal/8004@192.168.210.14:25491) Locked, Waiting on external entities
2023-04-26 00:47:30.688329 96.07% [DEBUG] switch_ivr_play_say.c:2001 done playing file local_stream://default
2023-04-26 00:47:30.688329 96.07% [DEBUG] switch_core_session.c:2983 sofia/internal/+18885551212@<ITSP> skip receive message [PHONE_EVENT] (channel is hungup already)
2023-04-26 00:47:30.688329 96.07% [DEBUG] switch_ivr_bridge.c:568 sofia/internal/+18885551212@<ITSP> skip receive message [BRIDGE] (channel is hungup already)
2023-04-26 00:47:30.688329 96.07% [DEBUG] switch_ivr.c:679 sofia/internal/+18885551212@<ITSP> skip receive message [VIDEO_SYNC] (channel is hungup already)
2023-04-26 00:47:30.688329 96.07% [DEBUG] switch_ivr_bridge.c:826 sofia/internal/+18885551212@<ITSP> ending bridge by request from read function
2023-04-26 00:47:30.688329 96.07% [DEBUG] switch_ivr_bridge.c:912 BRIDGE THREAD DONE [sofia/internal/+18885551212@<ITSP>]
2023-04-26 00:47:30.688329 96.07% [DEBUG] switch_ivr_bridge.c:1895 sofia/internal/+18885551212@<ITSP> skip receive message [UNBRIDGE] (channel is hungup already)
2023-04-26 00:47:30.688329 96.07% [NOTICE] switch_core_session.c:1771 Session 396932 (sofia/internal/8004@192.168.210.14:25491) Ended
2023-04-26 00:47:30.688329 96.07% [NOTICE] switch_core_session.c:1775 Close Channel sofia/internal/8004@192.168.210.14:25491 [CS_DESTROY]