Callers randomly being put on hold, callee drops

[darkpixel (Aaron C. de Bruyn)]

This didn’t get much traction the last time around:

Callers randomly being put on hold, callee drops

I’ve been running into a bizarre issue for the last few months, and I can’t seem to track it down. When someone makes a call (outside-to-inside our phone system, or inside-to-inside), they go through one of these paths: They will be in a queue to wait to talk to someone They will talk with someone and be put on hold (parked) to be answered by another phone They will pass through a ring group and talk to someone In all but the last ‘path’, something strange occasionally happens: The callee w…

And there are other threads that trail off without a solution:

Spontaneous parking with EPM on Digium phones

Another bit of information, I don’t know if it’s pertinent or not: I have set the ring groups to ignore busy extensions, because if the phone rings while someone is on a call, they then cannot park that call. This still happens, although much less frequently, if someone makes an extension to extension call within the office to someone who is on a call. Again, the end result is that if the phone rings while a call is in progress, then parking does not work on that call.

It’s absolutely horrible now.

I just listened to one call recording from a customer talking with an office manager. The office manager was only able to get one or two words out before the call would drop to hold music and be parked. The office manager would hit the parking button on her phone, pick up the call again, get one or two words out, and then it would go back on park again. It happened 5 or 6 times during one 3-minute call.

I’m wracking my brain as to what might be going on, but it’s happening at all of their 27 offices to varying degrees. Some offices have a call randomly park once or twice per hour and some are parking every few minutes or seconds.

I started out by rebooting all the phones. That didn’t fix it.

Every site has around a 45 msec ping time to the phone server and monitoring tools show a perfect connection with 0% packet loss over the previous 3 hours. One office had 0.1% packet loss, but that office is one that has the issue only a few times per day.

After listening to a few call recordings and doing some testing, I found out it occurs much more frequently when calls go through our call center and are parked by the call center before being transferred to the office.

The flow is this:

• Call comes in from one of our SIP trunk providers and they are presented with a menu (press 1 if you are a new patient, 2 if you are an existing patient).

• When they press 1 they are routed to the call center queue and one of the agents answers. The agent talks with the caller and realizes they need to transfer them to one of the offices, so they park the call in their private lot.

• The agent calls the ring group for the office and the manager picks up. They let the manager know what’s going on and that they will send them the call. They hang up.

• The agent unparks the call, says “I’ll transfer you now”, hits the transfer button on their phone and dials the ring group for the office and disconnects.

• The office answers the calls and that’s when the trouble starts. The caller gets parked in the offices private park group randomly, without warning, and without anyone hitting a button on their phone.

Here’s a snippet of the logs for one particular call:

[2022-08-31 15:07:11] VERBOSE[3911][C-00001474] app_queue.c: Local/2105@from-queue-00004253;1 answered PJSIP/Twilio-00003ccf
[2022-08-31 15:07:11] VERBOSE[14714][C-00001474] bridge_channel.c: Channel PJSIP/2105-00003d1b joined 'simple_bridge' basic-bridge <b7878a06-9107-4918-853d-608fcb6767bf>
[2022-08-31 15:07:11] VERBOSE[3911][C-00001474] res_musiconhold.c: Stopped music on hold on PJSIP/Twilio-00003ccf
[2022-08-31 15:07:11] VERBOSE[14425][C-00001474] bridge_channel.c: Channel Local/2105@from-queue-00004253;2 joined 'simple_bridge' basic-bridge <b7878a06-9107-4918-853d-608fcb6767bf>
[2022-08-31 15:07:11] VERBOSE[14715][C-00001474] bridge_channel.c: Channel Local/2105@from-queue-00004253;1 joined 'simple_bridge' basic-bridge <cd3c5569-f7af-40d0-80bb-32f0c3901621>
[2022-08-31 15:07:11] VERBOSE[3911][C-00001474] bridge_channel.c: Channel PJSIP/Twilio-00003ccf joined 'simple_bridge' basic-bridge <cd3c5569-f7af-40d0-80bb-32f0c3901621>
[2022-08-31 15:08:14] VERBOSE[14425][C-00001474] res_musiconhold.c: Started music on hold, class 'default', on channel 'Local/2105@from-queue-00004253;2'
[2022-08-31 15:10:53] VERBOSE[14425][C-00001474] res_musiconhold.c: Stopped music on hold on Local/2105@from-queue-00004253;2
[2022-08-31 15:10:53] VERBOSE[14714][C-00001474] bridge_channel.c: Channel PJSIP/2105-00003d1b left 'simple_bridge' basic-bridge <b7878a06-9107-4918-853d-608fcb6767bf>
[2022-08-31 15:10:54] VERBOSE[14425][C-00001474] bridge_channel.c: Channel Local/2105@from-queue-00004253;2 left 'simple_bridge' basic-bridge <d10cfdd5-c41e-402b-9c16-dc88fdacd422>
[2022-08-31 15:10:54] VERBOSE[14425][C-00001474] parking/parking_bridge.c: Parking 'Local/2105@from-queue-00004253;2' in 'parkinglot_21' at space 3351
[2022-08-31 15:10:54] VERBOSE[14425][C-00001474] bridge_channel.c: Channel Local/2105@from-queue-00004253;2 joined 'holding_bridge' parking-bridge <f2f9ae7c-6c00-4ec7-98e4-28801dd389ed>
[2022-08-31 15:10:54] VERBOSE[14425][C-00001474] res_musiconhold.c: Started music on hold, class 'default', on channel 'Local/2105@from-queue-00004253;2'
[2022-08-31 15:10:57] VERBOSE[14425][C-00001474] file.c: <Local/2105@from-queue-00004253;2> Playing 'beep.ulaw' (language 'en')
[2022-08-31 15:11:07] VERBOSE[14425][C-00001474] bridge_channel.c: Channel Local/2105@from-queue-00004253;2 left 'simple_bridge' basic-bridge <8bdc6b9e-c118-4928-82de-f3b8d309bc57>
[2022-08-31 15:11:07] VERBOSE[14425][C-00001474] parking/parking_bridge.c: Parking 'Local/2105@from-queue-00004253;2' in 'parkinglot_21' at space 3351
[2022-08-31 15:11:07] VERBOSE[14425][C-00001474] bridge_channel.c: Channel Local/2105@from-queue-00004253;2 joined 'holding_bridge' parking-bridge <f2f9ae7c-6c00-4ec7-98e4-28801dd389ed>
[2022-08-31 15:11:07] VERBOSE[14425][C-00001474] res_musiconhold.c: Started music on hold, class 'default', on channel 'Local/2105@from-queue-00004253;2'
[2022-08-31 15:11:09] VERBOSE[14425][C-00001474] file.c: <Local/2105@from-queue-00004253;2> Playing 'beep.ulaw' (language 'en')
[2022-08-31 15:11:20] VERBOSE[14425][C-00001474] bridge_channel.c: Channel Local/2105@from-queue-00004253;2 left 'simple_bridge' basic-bridge <78c8b3e7-fa4e-457c-9f68-8af399996727>
[2022-08-31 15:11:20] VERBOSE[14425][C-00001474] parking/parking_bridge.c: Parking 'Local/2105@from-queue-00004253;2' in 'parkinglot_21' at space 3351
[2022-08-31 15:11:20] VERBOSE[14425][C-00001474] bridge_channel.c: Channel Local/2105@from-queue-00004253;2 joined 'holding_bridge' parking-bridge <f2f9ae7c-6c00-4ec7-98e4-28801dd389ed>
[2022-08-31 15:11:20] VERBOSE[14425][C-00001474] res_musiconhold.c: Started music on hold, class 'default', on channel 'Local/2105@from-queue-00004253;2'
[2022-08-31 15:11:22] VERBOSE[14425][C-00001474] file.c: <Local/2105@from-queue-00004253;2> Playing 'beep.ulaw' (language 'en')

You can see it parking the call and the office manager un-parking the call every few seconds.

Every phone throughout the company is a Digum D60 running the latest firmware (1.50 although the issue has occurred for ~3 years now).

I just enabled syslogging on all the phones and I’m going to watch and see if there’s any clue in the debug output.

I can provide a log of the call from /var/log/asterisk/full if necessary, but I do have to redact the phone numbers.

Any other ideas?

[thetelcoguy (telcoguy)]

It sounds like your system got hacked
Or there is some malicious script

Can you try setting up one of the phones from scratch on a temp freepbx instance (like on a VM) and see if the issue still happens? If the issue is so complicated as this then sometimes it can be beneficial to start from scratch.

[darkpixel (Aaron C. de Bruyn)]

I highly doubt that.

Why would someone compromise a phone system to implant some code that makes Asterisk toss calls back into a park group randomly over a period of several years only to “crank it up” in the last few weeks? I mean…that’s a really specific way of screwing with a company…as opposed to just compromising the box and making spam calls…or trying to listen to calls in hopes someone drops a card number or social security number…

[thetelcoguy (telcoguy)]

The issue is peculiar but what other setting could cause your calls to be put on park and having the action seem like it’s the user??? I have nothing else that comes to mind so try setting up a phone on a fresh instance and see if it happens. If it doesn’t happen and you have checked everything then maybe the phones were somehow compromised or someone is using action URI on them as some phones support call operations that way?? maybe your competition hacked the system in this way to make it seem like it’s not a hack since they know the possibility of hack would be so heavily doubted?? park and announce config gone wrong?? Or a phone has a softkey set as ## and your park extension, so in other words a transfer/hold/etc. key could be misprogrammed as a transfer to park key… a thousand possibilities. I’d first try setting a phone up on a new instance and see if the issue persists. Or try doing a network packet trace to see from what else is going on during the mysterious auto-parking you’re having.

[darkpixel (Aaron C. de Bruyn)]

I initially thought it could be user error…but this is happening at 27 different locations and multiple users at each location. I don’t think ~50 users would all be accidentally hitting the park button.

As for setting up a new instance of FreePBX to test, I don’t really have to. I run FreePBX internally with D60 and D65 phones.

The setup is even similar. Calls go into a queue, an agent answers, and then transfers it to a extension (not a ring group)…but it’s still pretty darned similar. Granted, this customer handles several thousand calls per day where we handle maybe 200.

I looked at the syslogs from the D60 phones that were having the trouble and it’s unfortunately difficult to tell because there doesn’t appear to be any documentation on what “KEY 99-[ c] 0” means other than it’s a keypress. But lining up the timestamps it appears the keypress is after the call magically goes on hold and it’s the office manager hitting the button to bring up the park screen to pick up the parked call.

Aug 31 21:48:02 192.168.142.102 core[745]:  callbridge: 15:48:02.728 src/broadcom_p  .....pjsua_check_snd_dev_idle no-op 
Aug 31 22:02:27 192.168.142.102 core[745]:  callbridge: 16:02:27.594 on_incoming_ca  ..Incoming call dflt_id:2  acc_id:1  call_id:7  from "REDACTED NAME" <sip:[email protected]>!!
Aug 31 22:02:29 192.168.142.102 phone:  call_photo_result cURL error file:/tmp/2113.png event:response.id.guiPho_2113.ResponseType.cURL.InternalErrors.404
Aug 31 22:02:29 192.168.142.102 phone:  call_photo_result cURL error file:/tmp/2113.png event:response.id.guiPho_2113.ResponseType.cURL.InternalErrors.404
Aug 31 22:02:34 192.168.142.102 core[745]:  callbridge: 16:02:34.622 src/broadcom_p  ..........pjsua_check_snd_dev_idle no-op 
Aug 31 22:03:59 192.168.142.102 core[745]:  callbridge: 16:04:00.142 on_incoming_ca  ..Incoming call dflt_id:2  acc_id:1  call_id:8  from "REDACTED-NAME" <sip:[email protected]>!!
Aug 31 22:04:01 192.168.142.102 phone:  call_photo_result cURL error file:/tmp/5416193777.png event:response.id.guiPho_5416193777.ResponseType.cURL.InternalErrors.404
Aug 31 22:04:01 192.168.142.102 phone:  call_photo_result cURL error file:/tmp/5416193777.png event:response.id.guiPho_5416193777.ResponseType.cURL.InternalErrors.404
Aug 31 22:04:19 192.168.142.102 core[745]:  callbridge: 16:04:20.126 src/broadcom_p  ..........pjsua_check_snd_dev_idle no-op 
Aug 31 22:09:00 192.168.142.102 core[745]:  callbridge: 16:09:01.123 on_incoming_ca  ..Incoming call dflt_id:2  acc_id:1  call_id:9  from "Zoie Randall" <sip:[email protected]>!!
Aug 31 22:09:04 192.168.142.102 phone:  call_photo_result cURL error file:/tmp/2105.png event:response.id.guiPho_2105.ResponseType.cURL.InternalErrors.404
Aug 31 22:09:04 192.168.142.102 phone:  call_photo_result cURL error file:/tmp/2105.png event:response.id.guiPho_2105.ResponseType.cURL.InternalErrors.404
Aug 31 22:09:06 192.168.142.102 core[745]:  callbridge: 16:09:06.898 src/broadcom_p  ..........pjsua_check_snd_dev_idle no-op 
Aug 31 22:09:22 192.168.142.102 xyz:  KEY 99-[ c ] 1
Aug 31 22:09:22 192.168.142.102 xyz:  AppScreen::redraw()
Aug 31 22:09:22 192.168.142.102 ae:  app parking_freepbx shown.
Aug 31 22:09:22 192.168.142.102 ae:  cURL::init Method GET Url https://voice.customer.tld:3443/applications.php/parking/main?user=3304&linestate= SSL Secure
Aug 31 22:09:22 192.168.142.102 xyz:  KEY 99-[ c ] 0
Aug 31 22:09:22 192.168.142.102 xyz:  KEY 49-[ 1 ] 1
Aug 31 22:09:22 192.168.142.102 ae:  hiding apps per dbus request.
Aug 31 22:09:22 192.168.142.102 ae:  hiding app contacts show failed.
Aug 31 22:09:22 192.168.142.102 ae:  hiding app appscreen show failed.
Aug 31 22:09:22 192.168.142.102 ae:  hiding app phonemenu show failed.
Aug 31 22:09:22 192.168.142.102 ae:  hiding app parking_freepbx show failed.
Aug 31 22:09:23 192.168.142.102 ae:  hiding app contactmanager_freepbx show failed.
Aug 31 22:09:23 192.168.142.102 core[745]:  callbridge: 16:09:23.322 src/broadcom_p  .pjsua_set_snd_dev no-op
Aug 31 22:09:23 192.168.142.102 ae:  hiding app donotdisturb_freepbx show failed.
Aug 31 22:09:23 192.168.142.102 xyz:  KEY 49-[ 1 ] 0
Aug 31 22:09:23 192.168.142.102 ae:  parking_freepbx: Showing page of type directory.
Aug 31 22:09:23 192.168.142.102 xyz:  KEY 75-[ K ] 0
Aug 31 22:09:24 192.168.142.102 phone:  call_photo_result cURL error file:/tmp/3351.png event:response.id.guiPho_3351.ResponseType.cURL.InternalErrors.404
Aug 31 22:09:26 192.168.142.102 phone:  call_photo_result cURL error file:/tmp/3351.png event:response.id.guiPho_3351.ResponseType.cURL.InternalErrors.404
Aug 31 22:09:33 192.168.142.102 ae:  cURL::init Method GET Url https://voice.customer.tld:3443/applications.php/parking/main?user=3304&linestate=CONNECTED SSL Secure
Aug 31 22:09:36 192.168.142.102 ae:  parking_freepbx: Showing page of type action.
Aug 31 22:09:36 192.168.142.102 core[745]:  callbridge: 16:09:36.708 src/broadcom_p  .....pjsua_check_snd_dev_idle no-op 
Aug 31 22:09:36 192.168.142.102 ae:  parking_freepbx: builtin_callapi.js:65: TypeError: undefined is not a function
Aug 31 22:09:36 192.168.142.102 ae:  parking_freepbx:             handler(msg) ;
Aug 31 22:09:36 192.168.142.102 core[745]:  callbridge: 16:09:36.769    src/state.c  .......validate_call_state: Error getting call info for call_id 10
Aug 31 22:09:36 192.168.142.102 core[745]:  callbridge: 16:09:36.774    src/state.c  .......validate_call_state: Error getting call info for call_id 10
Aug 31 22:09:36 192.168.142.102 ae:  parking_freepbx:  
Aug 31 22:09:36 192.168.142.102 ae:  parking_freepbx:  
Aug 31 22:09:36 192.168.142.102 ae:  parking_freepbx:  

The phones do have a “Park” soft button. It’s set to the REST-Parking action.

As for why a hack would be so heavily doubted, I would say it comes down to probabilities.

How many phone servers get compromised? Probably a lot.
How many people compromising phone servers are doing it to make free calls, place spam calls, or gather intel? Probably most of them.
How many people compromising phone servers are “competitors” that are risking their business being sued into the ground should they be caught who have decided to write some sort of module or change the FreePBX code to inject some garbage that randomly place calls on hold? I’d bet zero.

I mean…if someone was having one-way audio issues with calls, would your first thought be “It must be aliens preparing to invade earth”? Or maybe something like NAT issues?

Granted, this does seem like an unusual issue, but I think there are plenty of possibilities that are significantly more common than being hacked.

I’m going to try and grab packets for one of the offices from both their router and from the phone server for 24 hours and see if I can figure something out from that.

[darkpixel (Aaron C. de Bruyn)]

After more testing, I think I have this narrowed down a bit.
If the phone gets rebooted the issue goes away for a while.

Last night I rebooted ~250 phones and this morning there have been zero complaints.

I’m betting the issue will come back within a week.

Seems like a Digium firmware bug…

[darkpixel (Aaron C. de Bruyn)]

It seems to happen if the phone stay up for about a week.

The solution is to either reboot the phones every 4-5 days or to pay for support to get someone interested enough to fix it.

[rsmithuk (Richard Smith)]

Is there a router with SIP ALG enabled anywhere. I’ve seen behaviour like this caused by SIP ALG previously.

[darkpixel (Aaron C. de Bruyn)]

Nope. The routers are FreeBSD boxes. Nothing installed that tries to mess with SIP traffic.

[darkpixel (Aaron C. de Bruyn)]

This is driving my clients nuts.
Rebooting all the phones once a day seems to keep it mostly in check, but it seems to be somewhat random about when calls magically drop back to being on-hold.

I got a solid set of logs from it happening at one location and added a few notes:

# Call comes into a ring group and rings the phones:
[2022-09-14 11:33:19] VERBOSE[24619][C-00006628] app_dial.c: PJSIP/4407-00014d07 is ringing
[2022-09-14 11:33:19] VERBOSE[24619][C-00006628] app_dial.c: PJSIP/4405-00014d06 is ringing
[2022-09-14 11:33:19] VERBOSE[24619][C-00006628] app_dial.c: PJSIP/4404-00014d05 is ringing
[2022-09-14 11:33:19] VERBOSE[24619][C-00006628] app_dial.c: PJSIP/4402-00014d04 is ringing

# ext 4402 picks up the call, talks with the caller:
[2022-09-14 11:33:22] VERBOSE[24619][C-00006628] app_dial.c: PJSIP/4402-00014d04 answered PJSIP/Twilio-00014d03
[2022-09-14 11:33:22] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-auto-blkvm:1] ExecIf("PJSIP/4402-00014d04", "0?Set(CDR(recordingfile)=.wav)") in new stack
[2022-09-14 11:33:22] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-auto-blkvm:2] Set("PJSIP/4402-00014d04", "__MACRO_RESULT=") in new stack
[2022-09-14 11:33:22] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-auto-blkvm:3] Set("PJSIP/4402-00014d04", "CFIGNORE=") in new stack
[2022-09-14 11:33:22] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-auto-blkvm:4] Set("PJSIP/4402-00014d04", "MASTER_CHANNEL(CFIGNORE)=") in new stack
[2022-09-14 11:33:22] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-auto-blkvm:5] Set("PJSIP/4402-00014d04", "FORWARD_CONTEXT=from-internal") in new stack
[2022-09-14 11:33:22] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-auto-blkvm:6] Set("PJSIP/4402-00014d04", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
[2022-09-14 11:33:22] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-auto-blkvm:7] Macro("PJSIP/4402-00014d04", "blkvm-clr,") in new stack
[2022-09-14 11:33:22] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-blkvm-clr:1] Set("PJSIP/4402-00014d04", "SHARED(BLKVM,PJSIP/Twilio-00014d03)=") in new stack
[2022-09-14 11:33:22] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-blkvm-clr:2] Set("PJSIP/4402-00014d04", "GOSUB_RETVAL=") in new stack
[2022-09-14 11:33:22] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-blkvm-clr:3] MacroExit("PJSIP/4402-00014d04", "") in new stack
[2022-09-14 11:33:22] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-auto-blkvm:8] ExecIf("PJSIP/4402-00014d04", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=4402/sip:[email protected]:55038;ob)") in new stack
[2022-09-14 11:33:22] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-auto-blkvm:9] ExecIf("PJSIP/4402-00014d04", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=)") in new stack
[2022-09-14 11:33:22] VERBOSE[25799][C-00006628] bridge_channel.c: Channel PJSIP/4402-00014d04 joined 'simple_bridge' basic-bridge <babb54f0-11a2-443f-ba89-28fab0f2423b>
[2022-09-14 11:33:22] VERBOSE[24619][C-00006628] bridge_channel.c: Channel PJSIP/Twilio-00014d03 joined 'simple_bridge' basic-bridge <babb54f0-11a2-443f-ba89-28fab0f2423b>

# ext 4402 parks the caller:
[2022-09-14 11:33:51] VERBOSE[24619][C-00006628] bridge_channel.c: Channel PJSIP/Twilio-00014d03 left 'simple_bridge' basic-bridge <babb54f0-11a2-443f-ba89-28fab0f2423b>
[2022-09-14 11:33:51] VERBOSE[24619][C-00006628] parking/parking_bridge.c: Parking 'PJSIP/Twilio-00014d03' in 'parkinglot_34' at space 4451
[2022-09-14 11:33:51] VERBOSE[24619][C-00006628] bridge_channel.c: Channel PJSIP/Twilio-00014d03 joined 'holding_bridge' parking-bridge <7f445761-ff5a-4b86-96ad-6b5773c773e1>
[2022-09-14 11:33:51] VERBOSE[24619][C-00006628] res_musiconhold.c: Started music on hold, class 'default', on channel 'PJSIP/Twilio-00014d03'
[2022-09-14 11:33:51] VERBOSE[25799][C-00006628] file.c: <PJSIP/4402-00014d04> Playing 'digits/4.ulaw' (language 'en')
[2022-09-14 11:33:51] VERBOSE[25799][C-00006628] file.c: <PJSIP/4402-00014d04> Playing 'digits/4.ulaw' (language 'en')
[2022-09-14 11:33:51] VERBOSE[25799][C-00006628] file.c: <PJSIP/4402-00014d04> Playing 'digits/5.ulaw' (language 'en')
[2022-09-14 11:33:51] VERBOSE[25799][C-00006628] file.c: <PJSIP/4402-00014d04> Playing 'digits/1.ulaw' (language 'en')
[2022-09-14 11:33:51] VERBOSE[25799][C-00006628] bridge_channel.c: Channel PJSIP/4402-00014d04 left 'simple_bridge' basic-bridge <babb54f0-11a2-443f-ba89-28fab0f2423b>

# corresponding debug logs from ext 4402 during parking:
Sep 14 18:33:22 192.168.142.102 phone:  Unknown state in update_call(): call_status.CONNECTING.1.5247-46."REDACTED-CALLER-NAME" <sip:REDACTED-CALLER-PHONE-NUMBER@pho\.ne\.svr\.ip>.<sip:asterisk@pho\.ne\.srv\.ip:5060>.200.OK.active.role.callee.local_info.<sip:4402@our\.use\.r\.ip;ob
Sep 14 18:33:50 192.168.142.102 xyz:  KEY 99-[ c ] 1
Sep 14 18:33:50 192.168.142.102 xyz:  AppScreen::redraw()
Sep 14 18:33:50 192.168.142.102 ae:  app parking_freepbx shown.
Sep 14 18:33:50 192.168.142.102 ae:  cURL::init Method GET Url https://voice.customer.tld:3443/applications.php/parking/main?user=4402&linestate=CONNECTED SSL Secure
Sep 14 18:33:50 192.168.142.102 xyz:  KEY 99-[ c ] 0
Sep 14 18:33:51 192.168.142.102 ae:  parking_freepbx: Showing page of type action.
Sep 14 18:33:51 192.168.142.102 ae:  hiding apps per dbus request.
Sep 14 18:33:51 192.168.142.102 ae:  hiding app contacts show failed.
Sep 14 18:33:51 192.168.142.102 ae:  hiding app appscreen show failed.
Sep 14 18:33:51 192.168.142.102 ae:  hiding app phonemenu show failed.
Sep 14 18:33:51 192.168.142.102 ae:  hiding app parking_freepbx show failed.
Sep 14 18:33:51 192.168.142.102 ae:  hiding app contactmanager_freepbx show failed.
Sep 14 18:33:51 192.168.142.102 ae:  hiding app donotdisturb_freepbx show failed.
Sep 14 18:33:52 192.168.142.102 core[5247]:  callbridge: 12:33:52.233 src/broadcom_p  .....pjsua_check_snd_dev_idle no-op 
Sep 14 18:33:52 192.168.142.102 core[5247]:  callbridge: 12:33:52.240    src/state.c  .......validate_call_state: Error getting call info for call_id 25
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx: builtin_callapi.js:65: TypeError: undefined is not a function
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx:             handler(msg) ;
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx:  
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx:  
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx:  
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx:  
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx:  
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx:  
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx:  
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx:  
Sep 14 18:33:52 192.168.142.102 core[5247]:  callbridge: 12:33:52.298    src/state.c  .......validate_call_state: Error getting call info for call_id 25
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx:  
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx:  
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx:  
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx:  
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx: ^
Sep 14 18:33:52 192.168.142.102 ae:  parking_freepbx: TypeError: undefined is not a function#012    at CALL_NON_FUNCTION (native)#012    at builtin_callapi.js:65:13#012    at Array.forEach (native)#012    at Object.<anonymous> (builtin_callapi.js:64:25)#012    at handle_handled_call
# ext 4402 starts making an outbound call:
Sep 14 18:33:52 192.168.142.102 xyz:  KEY 75-[ K ] 1
Sep 14 18:34:53 192.168.142.102 xyz:  KEY 52-[ 4 ] 1
Sep 14 18:34:53 192.168.142.102 xyz:  KEY 52-[ 4 ] 0


# ext 4404 unparks the call, the caller hears the beep
[2022-09-14 11:34:09] VERBOSE[24619][C-00006628] file.c: <PJSIP/Twilio-00014d03> Playing 'beep.ulaw' (language 'en')

# corresponding debug logs from ext 4404 during parking:
Sep 14 18:34:08 192.168.142.104 ae:  cURL::init Method GET Url https://voice.customer.tld:3443/applications.php/parking/main?user=4404&linestate= SSL Secure
Sep 14 18:34:08 192.168.142.104 xyz:  KEY 99-[ c ] 0
Sep 14 18:34:08 192.168.142.104 xyz:  KEY 49-[ 1 ] 1
Sep 14 18:34:08 192.168.142.104 ae:  hiding apps per dbus request.
Sep 14 18:34:08 192.168.142.104 ae:  hiding app contacts show failed.
Sep 14 18:34:08 192.168.142.104 ae:  hiding app appscreen show failed.
Sep 14 18:34:08 192.168.142.104 ae:  hiding app phonemenu show failed.
Sep 14 18:34:08 192.168.142.104 ae:  hiding app parking_freepbx show failed.
Sep 14 18:34:08 192.168.142.104 core[3565]:  callbridge: 12:34:08.968 src/broadcom_p  .pjsua_set_snd_dev no-op
Sep 14 18:34:08 192.168.142.104 ae:  hiding app contactmanager_freepbx show failed.
Sep 14 18:34:08 192.168.142.104 ae:  hiding app donotdisturb_freepbx show failed.
Sep 14 18:34:09 192.168.142.104 ae:  parking_freepbx: Showing page of type directory.
Sep 14 18:34:09 192.168.142.104 xyz:  KEY 49-[ 1 ] 0
Sep 14 18:34:10 192.168.142.104 xyz:  KEY 75-[ K ] 0
Sep 14 18:34:11 192.168.142.104 phone:  call_photo_result cURL error file:/tmp/4451.png event:response.id.guiPho_4451.ResponseType.cURL.InternalErrors.404
Sep 14 18:34:11 192.168.142.104 phone:  call_photo_result cURL error file:/tmp/4451.png event:response.id.guiPho_4451.ResponseType.cURL.InternalErrors.404



# Here's where ext 4404 says the caller "magically" went back into park without hitting anything on the phone.  Ext 4404 can hear the call drop and starts bringing up the parking menu to connect to the call again:
[2022-09-14 11:34:20] VERBOSE[24619][C-00006628] bridge_channel.c: Channel PJSIP/Twilio-00014d03 left 'simple_bridge' basic-bridge <857056f6-0a3b-45a4-b979-132ed9ed0889>
[2022-09-14 11:34:20] VERBOSE[24619][C-00006628] parking/parking_bridge.c: Parking 'PJSIP/Twilio-00014d03' in 'parkinglot_34' at space 4451
[2022-09-14 11:34:20] VERBOSE[24619][C-00006628] bridge_channel.c: Channel PJSIP/Twilio-00014d03 joined 'holding_bridge' parking-bridge <7f445761-ff5a-4b86-96ad-6b5773c773e1>
[2022-09-14 11:34:20] VERBOSE[24619][C-00006628] res_musiconhold.c: Started music on hold, class 'default', on channel 'PJSIP/Twilio-00014d03'


# corresponding debug logs from ext 4404 showing them picking up the call that magically parked.  There is no gap between this and the previous log lines from this extension.
Sep 14 18:34:19 192.168.142.104 ae:  cURL::init Method GET Url https://voice.customer.tld:3443/applications.php/parking/main?user=4404&linestate=CONNECTED SSL Secure
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx: Showing page of type action.
Sep 14 18:34:20 192.168.142.104 core[3565]:  callbridge: 12:34:20.790 src/broadcom_p  .....pjsua_check_snd_dev_idle no-op 
Sep 14 18:34:20 192.168.142.104 core[3565]:  callbridge: 12:34:20.794    src/state.c  .......validate_call_state: Error getting call info for call_id 14
Sep 14 18:34:20 192.168.142.104 core[3565]:  callbridge: 12:34:20.798    src/state.c  .......validate_call_state: Error getting call info for call_id 14
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx: builtin_callapi.js:65: TypeError: undefined is not a function
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx:             handler(msg) ;
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx:  
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx:  
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx:  
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx:  
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx:  
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx:  
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx:  
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx:  
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx:  
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx:  
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx:  
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx:  
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx: ^
Sep 14 18:34:20 192.168.142.104 ae:  parking_freepbx: TypeError: undefined is not a function#012    at CALL_NON_FUNCTION (native)#012    at builtin_callapi.js:65:13#012    at Array.forEach (native)#012    at Object.<anonymous> (builtin_callapi.js:64:25)#012    at handle_handled_call
Sep 14 18:34:22 192.168.142.104 xyz:  KEY 99-[ c ] 1
Sep 14 18:34:22 192.168.142.104 xyz:  AppScreen::redraw()
Sep 14 18:34:22 192.168.142.104 ae:  app parking_freepbx shown.
Sep 14 18:34:22 192.168.142.104 ae:  cURL::init Method GET Url https://voice.customer.tld:3443/applications.php/parking/main?user=4404&linestate= SSL Secure
Sep 14 18:34:22 192.168.142.104 xyz:  KEY 99-[ c ] 0
Sep 14 18:34:22 192.168.142.104 ae:  parking_freepbx: Showing page of type directory.
Sep 14 18:34:23 192.168.142.104 xyz:  KEY 49-[ 1 ] 1
Sep 14 18:34:23 192.168.142.104 ae:  hiding apps per dbus request.
Sep 14 18:34:23 192.168.142.104 ae:  hiding app contacts show failed.
Sep 14 18:34:23 192.168.142.104 ae:  hiding app appscreen show failed.
Sep 14 18:34:23 192.168.142.104 ae:  hiding app phonemenu show failed.
Sep 14 18:34:23 192.168.142.104 ae:  hiding app parking_freepbx show failed.
Sep 14 18:34:23 192.168.142.104 ae:  hiding app contactmanager_freepbx show failed.
Sep 14 18:34:23 192.168.142.104 ae:  hiding app donotdisturb_freepbx show failed.
Sep 14 18:34:23 192.168.142.104 xyz:  KEY 49-[ 1 ] 0
Sep 14 18:34:23 192.168.142.104 core[3565]:  callbridge: 12:34:23.784 src/broadcom_p  .pjsua_set_snd_dev no-op


# ext 4404 successfully picks up the call and everyone hears the beep:
[2022-09-14 11:34:24] VERBOSE[24619][C-00006628] file.c: <PJSIP/Twilio-00014d03> Playing 'beep.ulaw' (language 'en')


# random additional junk in the 4404 debug logs:
Sep 14 18:34:25 192.168.142.104 phone:  call_photo_result cURL error file:/tmp/4451.png event:response.id.guiPho_4451.ResponseType.cURL.InternalErrors.404
Sep 14 18:34:26 192.168.142.104 phone:  call_photo_result cURL error file:/tmp/4451.png event:response.id.guiPho_4451.ResponseType.cURL.InternalErrors.404


# ext 4404 finishes up quickly with the caller and hangs up:
[2022-09-14 11:36:29] VERBOSE[24619][C-00006628] bridge_channel.c: Channel PJSIP/Twilio-00014d03 left 'simple_bridge' basic-bridge <86d462f8-d4e5-40bf-929e-09825e19bea5>
[2022-09-14 11:36:29] VERBOSE[24619][C-00006628] app_macro.c: Spawn extension (macro-dial, s, 37) exited non-zero on 'PJSIP/Twilio-00014d03' in macro 'dial'
[2022-09-14 11:36:29] VERBOSE[24619][C-00006628] pbx.c: Spawn extension (ext-group, 4401, 18) exited non-zero on 'PJSIP/Twilio-00014d03'
[2022-09-14 11:36:29] VERBOSE[24619][C-00006628] pbx.c: Executing [h@ext-group:1] Macro("PJSIP/Twilio-00014d03", "hangupcall,") in new stack
[2022-09-14 11:36:29] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/Twilio-00014d03", "1?theend") in new stack
[2022-09-14 11:36:29] VERBOSE[24619][C-00006628] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2022-09-14 11:36:29] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/Twilio-00014d03", "0?Set(CDR(recordingfile)=)") in new stack
[2022-09-14 11:36:29] VERBOSE[24619][C-00006628] pbx.c: Executing [s@macro-hangupcall:4] Hangup("PJSIP/Twilio-00014d03", "") in new stack
[2022-09-14 11:36:29] VERBOSE[24619][C-00006628] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/Twilio-00014d03' in macro 'hangupcall'
[2022-09-14 11:36:29] VERBOSE[24619][C-00006628] pbx.c: Spawn extension (ext-group, h, 1) exited non-zero on 'PJSIP/Twilio-00014d03'


# ext 4404 debug logs from the hang-up:
Sep 14 18:36:29 192.168.142.104 core[3565]:  callbridge: 12:36:29.162 sip_transactio !Failed to lock transaction for icmp; ignoring.
Sep 14 18:36:29 192.168.142.104 core[3565]:  callbridge: 12:36:29.182 sip_transactio  Failed to lock transaction for icmp; ignoring.
Sep 14 18:36:29 192.168.142.104 core[3565]:  callbridge: 12:36:29.375 src/broadcom_p  ......pjsua_check_snd_dev_idle no-op

Unfortunately there doesn’t appear to be any decent logging at the moment the call magically goes back on hold.

I’ve dug around the call flow and looked at settings and don’t see anything that could be related.
Calls come, match with an inbound route and play an IVR. This caller chose an option that dropped them into a ring group for the phones, and that’s where the asterisk log starts.

Each location has its own private park group (Parking Pro module).

[darkpixel (Aaron C. de Bruyn)]

I’m still able to keep this issue at bay by rebooting the phones every 24 hours.
If I let things go longer than that, some phones will “freak out” and start putting callers on hold every few seconds. Rebooting them using EPM resolves it for another 24 hours.

I’m starting to suspect It could be based on the number of calls a phone has taken. Maybe a buffer overflow in a counter or something.

[darkpixel (Aaron C. de Bruyn)]

This weekend we switched all phones from PJSIP to SIP.

There haven’t been any reports of issues yet this morning, but since the phones rebooted Sunday afternoon, I wouldn’t expect issues to start showing up until around 4 PM today.

[darkpixel (Aaron C. de Bruyn)]

Switching from SIP to PJSIP hasn’t worked. We’re still getting calls randomly put back on hold with errors like this showing up in the phone debug logs:

Sep 26 21:03:55 192.168.142.105 core[368]:  Thread [0xb5a2b480] sending com.digium.cbridge.resp.presence onto the [0] queue
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx: builtin_callapi.js:65: TypeError: undefined is not a function
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx:             handler(msg) ;
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx:  
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx:  
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx:  
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx:  
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx:  
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx:  
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx:  
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx:  
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx:  
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx:  
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx:  
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx:  
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx: ^
Sep 26 21:03:55 192.168.142.105 core[368]:  callbridge: state_foreach_ept_stream
Sep 26 21:03:55 192.168.142.105 core[368]:  callbridge: 14:03:56.772   pjsua_core.c  .RX 1024 bytes Request msg NOTIFY/cseq=293 (rdata0x2c665c) from UDP red.act.ed.ip:5160:
Sep 26 21:03:55 192.168.142.105 core[368]:  callbridge: 14:03:56.773   pjsua_core.c  ..TX 535 bytes Response msg 200/NOTIFY/cseq=293 (tdta0x2d1544) to UDP red.act.ed.ip:5160:
Sep 26 21:03:55 192.168.142.105 phone:  dbus_query_idle_apps()
Sep 26 21:03:55 192.168.142.105 phone:  dbus_hide_idle_apps()
Sep 26 21:03:55 192.168.142.105 ae:  parking_freepbx: TypeError: undefined is not a function#012    at CALL_NON_FUNCTION (native)#012    at builtin_callapi.js:65:13#012    at Array.forEach (native)#012    at Object.<anonymous> (builtin_callapi.js:64:25)#012    at handle_handled_call

It seems like the issue only happens when a call comes in, someone answers, parks the call, then someone else picks it up. i.e. “Hang on a sec and let me get them for you”.

Nearest I can guess based on the available logs is there’s a bug in the Digium Parking app as evidenced by the javascript error messages.

I’m going to go replace a bunch of Digium phones with Yealink phones over the next few days and see if that solves the issue.

[darkpixel (Aaron C. de Bruyn)]

Replaced two offices with Yealink phones yesterday. So far, zero issues with the Yealink phones while other sites using Digium phones continue to suffer from calls randomly getting parked.

[darkpixel (Aaron C. de Bruyn)]

It’s been 3 weeks.

Yealink phones are working well. Digium phones are still having non-stop issues with callers being randomly parked.

The CEO just said “No more Digum phones. Order Yealink phones going forward. We’re opening 8 new offices by January 1st, so you are approved to order 75 new Yealink phones, and we’ll discuss replacing all the existing Digium phones in December.”

This bums me out a bit. Digium used to be a spectacular company to work with. I’ve used them since the early 2000s and the good 'ol days of managing tens of PRI cards at an ISP that ran Asterisk and handled a few hundred thousand calls per day. You could pick up a phone and talk with an engineer about software issues.

Now it appears they’re tripping over $25,000 in phone sales because of a $500 support credit pack.

Oh well.