Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Outbound Calls - Random Fast Busy/Drop #606

Open
Ruler2112 opened this issue Jan 31, 2024 · 0 comments
Open

Outbound Calls - Random Fast Busy/Drop #606

Ruler2112 opened this issue Jan 31, 2024 · 0 comments

Comments

@Ruler2112
Copy link

History

We were sold the high availability module by Sangoma with their specialized hardware so that we have a hot-spare server - something happens to one server, all services and the IP automatically migrate to the second with shared mirrored file systems. Unbeknownst to me at the time, they were sunsetting this feature when they sold us the very expensive module. We do not want to lose this, especially after the significant investment, so are stuck on an old version of the PBX / Asterisk - Version 10.13.66-22. I installed the SCCP module shortly after we got the system in 2019, but ran into vague undefined problems that users would not provide details about. Since the Cisco 7960 phones worked fine on SIP, I just used the SIP firmware, despite it being slow and kinda buggy.

This worked fine until the middle of last year, when an update to our edge device nuked the 7960 phones running the SIP firmware - outbound calls would connect and start playing normal audio. Randomly on about 20% of the calls, the incoming audio would be silent for 1-4 seconds, then the audio would be perfect for the rest of the call no matter how long it lasted. None of the other brand/model phones running SIP had this behavior - only the Cisco 7960 phones. After much troubleshooting, I put a network tap in to capture exactly what was going to the phone... reconstructing the RTP streams revealed that the phone was being sent the proper audio, but they were not playing it. Reverting to the old firmware on our edge device was not possible due to nobody reporting this issue until after the 2-week period in which Meraki allows us to revert it. (Still don't have an even semi-viable theory as to how/why a firmware change on an edge router would affect a specific model/firmware phone like this, especially when the audio is arriving at the phone intact...)

At this time, I revisited the SCCP module. Tried updating to the latest version, but could not due to being locked on older software as already described & I do not know how to determine which is the most recent version I could compile. A user who actually wanted to work with me with testing was invaluable and I found settings that work with our environment. One of the major things was that the sound of the destination ringing would not be played when making outbound calls - found that setting EarlyRTP to Progress rather than None fixed this because it poked a hole in our firewall for the return RTP stream to use. I flashed a bunch of phones back to skinny, destroyed the extensions on the PBX, recreated them as sccp extensions, and we've been running this way since. Everything has worked perfectly... until about 3 weeks ago.

Reproduction Steps:

It is not consistently reproducible. Happens maybe 15-20 times a day.

chan-sccp version:

I'm sorry - I do not know how to find the version number. Files have a date/time stamp of October 8, 2019. Given the restrictions listed above and compiler requirements for the newest version, I am unable to update to the latest revision. :( If this precludes the possibility of getting support / help, I will certainly understand.

asterisk version:

PBXact Version 10.13.66-22
Asterisk 13.23.1

Expected behavior:

The call connects normally when a user places a call.

Observed behavior:

When users who are using the Cisco 7960 phones running SCCP firmware make a call, the call will connect and start ringing, then go fast busy for a few seconds and the call is dropped. If the called party answers immediately, they will sometime hear the person before it goes fast busy and disconnects. This happens on both internal calls and calls to the outside. It is random and affects a relatively low percentage of calls, but is extremely annoying and rather disruptive when it does. Nothing has been changed in our network, firmware of the phones, or PBX configuration since well before this symptom was reported. The call recordings for calls that I have received details of have all been of 0 second duration. I've tried setting EarlyRTP on one phone to RingOut on one phone, but it had no impact. I just now changed it to Dial for one phone, but really don't hold out much hope of this fixing the issue.

Addition / Optional Information:

After scouring the log files, I discovered the following. This is an excerpt from a call from one skinny extension to another skinny phone, not hitting our trunk:
`
[2024-01-30 14:47:32] VERBOSE[16472][C-00003d1e] pbx.c: Executing [s@func-apply-sipheaders:14] Return("SCCP/3037-0000A488", "") in new stack

[2024-01-30 14:47:32] VERBOSE[16472][C-00003d1e] app_stack.c: Spawn extension (from-internal, 3037, 1) exited non-zero on 'SCCP/3037-0000A488'

[2024-01-30 14:47:32] VERBOSE[16472][C-00003d1e] app_stack.c: SCCP/3037-0000A488 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=

[2024-01-30 14:47:32] VERBOSE[16472][C-00003d1e] : -- SCCP: Asterisk request to call SCCP/3037-0000A488 (dest:3037, timeout: 0)

[2024-01-30 14:47:32] VERBOSE[16472][C-00003d1e] : -- 3037: Asterisk request to call SCCP/3037-0000A488

[2024-01-30 14:47:32] VERBOSE[16472][C-00003d1e] : -- SCCP/3037: Incoming calls:0, Incoming calls limit: 6

[2024-01-30 14:47:32] VERBOSE[16472][C-00003d1e] : -- SCCP/3037-0000A488: (sccp_pbx_call) Returning: 0

[2024-01-30 14:47:32] VERBOSE[16472][C-00003d1e] app_dial.c: Called SCCP/3037

[2024-01-30 14:47:32] VERBOSE[16472][C-00003d1e] app_dial.c: SCCP/3037-0000A488 is ringing

[2024-01-30 14:47:39] VERBOSE[3268][C-00000080] : SCCP: Timeout for call 'SCCP/3036-0000A487'. Nothing to dial -> INVALIDNUMBER

[2024-01-30 14:47:46] VERBOSE[10930][C-00003d1e] : -- SEP000F902B5100: is Onhook (buttonIndex: 1, callid: 42119)

[2024-01-30 14:47:46] VERBOSE[10930][C-00003d1e] : == SEP000F902B5100: Ending call SCCP/3036-0000A487 (state:INVALIDNUMBER)

[2024-01-30 14:47:46] VERBOSE[10930][C-00003d1e] : -- SEP000F902B5100: Sending hangupRequest to Call SCCP/3036-0000A487 (state: INVALIDNUMBER)

[2024-01-30 14:47:46] VERBOSE[16472][C-00003d1e] app_macro.c: Spawn extension (macro-dial-one, s, 60) exited non-zero on 'SCCP/3036-0000A487' in macro 'dial-one'

[2024-01-30 14:47:46] VERBOSE[16472][C-00003d1e] app_macro.c: Spawn extension (macro-exten-vm, s, 14) exited non-zero on 'SCCP/3036-0000A487' in macro 'exten-vm'

[2024-01-30 14:47:46] VERBOSE[16472][C-00003d1e] pbx.c: Spawn extension (ext-local, 3037, 2) exited non-zero on 'SCCP/3036-0000A487'

[2024-01-30 14:47:46] VERBOSE[16472][C-00003d1e] pbx.c: Executing [h@ext-local:1] Macro("SCCP/3036-0000A487", "hangupcall,") in new stack

[2024-01-30 14:47:46] VERBOSE[16472][C-00003d1e] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SCCP/3036-0000A487", "1?theend") in new stack

[2024-01-30 14:47:46] VERBOSE[16472][C-00003d1e] pbx_builtins.c: Goto (macro-hangupcall,s,3)

[2024-01-30 14:47:46] VERBOSE[16472][C-00003d1e] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SCCP/3036-0000A487", "0?Set(CDR(recordingfile)=)") in new stack

[2024-01-30 14:47:46] VERBOSE[16472][C-00003d1e] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SCCP/3036-0000A487", "") in new stack

[2024-01-30 14:47:46] VERBOSE[16472][C-00003d1e] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SCCP/3036-0000A487' in macro 'hangupcall'

[2024-01-30 14:47:46] VERBOSE[16472][C-00003d1e] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'SCCP/3036-0000A487'

[2024-01-30 14:47:46] VERBOSE[16473][C-00003d1e] app_mixmonitor.c: MixMonitor close filestream (mixed)

[2024-01-30 14:47:46] VERBOSE[16473][C-00003d1e] app_mixmonitor.c: End MixMonitor Recording SCCP/3036-0000A487

[2024-01-30 14:47:46] VERBOSE[10930][C-00003d1e] : -- QualityStats: MLQK=0.0000;MLQKav=0.0000;MLQKmn=0.0000;MLQKmx=0.0000;MLQKvr=0.95;CCR=0.0000;ICR=0.0000;ICRmx=0.0000;CS=0;SCS=0

[2024-01-30 14:47:46] VERBOSE[10930][C-00003d1e] : -- SEP000F902B5100: Call Statistics:
[
Last Call : CallID: 42119 Packets sent: 372 rcvd: 0 lost: 0 jitter: 0 latency: 0
Last Quality : MLQK=0.0000;MLQKav=0.0000;MLQKmn=0.0000;MLQKmx=0.0000;MLQKvr=0.95|ICR=0.0000;CCR=0.0000;ICRmx=0.0000|CS=0;SCS=0
Mean Statistics : #Calls: 10 Packets sent: 3083 rcvd: 2891 lost: 0 jitter: 0 latency: 0
Mean Quality : MLQK=2.8965;MLQKav=3.1098;MLQKmn=2.8538;MLQKmx=4.5000;MLQKvr=0.95|ICR=0.0107;CCR=0.0026;ICRmx=0.0902|CS=5;SCS=0
]
`

I found #446 that has the same wording in the logs as I've found in my logs ("Nothing to dial -> INVALIDNUMBER"), but the fix for that issue is dated 8 months before the file dates of the version I have. Plus, it's related to transferring calls from a PJSIP to SCCP extension, whereas this is only affecting placed calls, not transfers. Our trunk is configured with chan_sip, not PJSIP, though I wouldn't think it would matter given that it's affecting extension-extension calls.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant