[Home]

Summary:ASTERISK-29393: app_mixmonitor: B option can cause fallthrough errors (and not work)
Reporter:N A (InterLinked)Labels:patch
Date Opened:2021-04-14 21:41:54Date Closed:
Priority:MinorRegression?
Status:Open/NewComponents:Applications/app_mixmonitor
Versions:18.3.0 Frequency of
Occurrence		Constant
Related
Issues:
Environment:Debian 10Attachments:( 0) ASTERISK-29393.diff
( 1) debug.txt
( 2) debug.txt
( 3) rtpcli.txt
Description:I'm not sure how much of this is related to ASTERISK-24397, but it seems to be a bit different, so I'm filing this just in case.

Two things:
1. When using the B option, I don't hear a beep every 15 seconds on either the calling or called channel as the documentation suggests, or in the finalized wav recording. But this might very well be because of the limitations of ChanSpy discussed in ASTERISK-24397. I gave up using ChanSpy and had to develop a hacky ConfBridge workaround for certain applications for the same reason. However, even with constant media flow, the beeps do not sound. Per the CLI printout below, they are getting played, but not audibly into the channel. This diverges from my experiences with ChanSpy, which did work when there was a media flow. I'm not getting beeps anywhere even with a good constant media flow.

2. Something I am more certain is not expected is that I get this each time the audiohook channel hangs up:
{noformat}
[2021-04-14 22:15:47] WARNING[12757][C-0000140e]: pbx.c:4576 __ast_pbx_run: Timeout, but no rule 't' or 'e' in context '__func_periodic_hook_context__'
{noformat}
Of course, I didn't write the func_periodic_hook_context context, so it's not something with the dialplan configuration.

This happens every time ChanSpy hangs up - every 15 seconds as we start the beep cycle over. Likely unrelated to why the beep doesn't sound, and seems to be some kind of fallthrough somewhere, but in case that is relevant to the way other things may not work properly, thought I'd surface that here.

Below, I have posted everything pertinent to MixMonitor, cutting out other things that were going in-between:
{noformat}
[Apr 14 22:15:36]   == Begin MixMonitor Recording SIP/ATAxLA1-000006d0
[Apr 14 22:15:36]     -- Called hook@__func_periodic_hook_context__
[Apr 14 22:15:36]     -- Executing [hook@__func_periodic_hook_context__:1] Set("Local/hook@__func_periodic_hook_context__-000011c1;2", "EncodedChannel=SIP/ATAxLA1-000006d0") in new stack
[Apr 14 22:15:36]     -- Executing [hook@__func_periodic_hook_context__:2] Set("Local/hook@__func_periodic_hook_context__-000011c1;2", "GROUP_NAME=SIP/ATAxLA1-000006d02") in new stack
[Apr 14 22:15:36]     -- Executing [hook@__func_periodic_hook_context__:3] Set("Local/hook@__func_periodic_hook_context__-000011c1;2", "GROUP(periodic-hook)=SIP/ATAxLA1-000006d02") in new stack
[Apr 14 22:15:36]     -- Executing [hook@__func_periodic_hook_context__:4] ExecIf("Local/hook@__func_periodic_hook_context__-000011c1;2", "0?Hangup()") in new stack
[Apr 14 22:15:36]     -- Executing [hook@__func_periodic_hook_context__:5] Set("Local/hook@__func_periodic_hook_context__-000011c1;2", "ChannelToSpy=SIP/ATAxLA1-000006d0") in new stack
[Apr 14 22:15:36]     -- Executing [hook@__func_periodic_hook_context__:6] ChanSpy("Local/hook@__func_periodic_hook_context__-000011c1;2", "SIP/ATAxLA1-000006d0,qEB") in new stack
[Apr 14 22:15:36]     -- Local/hook@__func_periodic_hook_context__-000011c1;1 answered
[Apr 14 22:15:36]     -- Executing [beep@__func_periodic_hook_context__:1] Answer("Local/hook@__func_periodic_hook_context__-000011c1;1", "") in new stack
[Apr 14 22:15:36]     -- Executing [beep@__func_periodic_hook_context__:2] Playback("Local/hook@__func_periodic_hook_context__-000011c1;1", "beep") in new stack
[Apr 14 22:15:36]     -- <Local/hook@__func_periodic_hook_context__-000011c1;1> Playing 'beep.ulaw' (language 'en')
[Apr 14 22:15:36]   == Spying on channel SIP/ATAxLA1-000006d0
[Apr 14 22:15:36]     -- Attaching spy channel Local/hook@__func_periodic_hook_context__-000011c1;2 to SIP/ATAxLA1-000006d0
[Apr 14 22:15:36]     -- Attaching spy channel Local/hook@__func_periodic_hook_context__-000011c1;2 to SIP/ATAxLA1-000006d0
[2021-04-14 22:15:47] WARNING[12757][C-0000140e]: pbx.c:4576 __ast_pbx_run: Timeout, but no rule 't' or 'e' in context '__func_periodic_hook_context__'
[Apr 14 22:15:47]   == Done Spying on channel SIP/ATAxLA1-000006d0
[Apr 14 22:15:47]     -- Stopped spying due to the spied-on channel hanging up.
[Apr 14 22:15:47]   == Spawn extension (__func_periodic_hook_context__, hook, 6) exited non-zero on 'Local/hook@__func_periodic_hook_context__-000011c1;2'
[Apr 14 22:15:51]     -- Called hook@__func_periodic_hook_context__
[Apr 14 22:15:51]     -- Executing [hook@__func_periodic_hook_context__:1] Set("Local/hook@__func_periodic_hook_context__-000011c2;2", "EncodedChannel=SIP/ATAxLA1-000006d0") in new stack
[Apr 14 22:15:51]     -- Executing [hook@__func_periodic_hook_context__:2] Set("Local/hook@__func_periodic_hook_context__-000011c2;2", "GROUP_NAME=SIP/ATAxLA1-000006d02") in new stack
[Apr 14 22:15:51]     -- Executing [hook@__func_periodic_hook_context__:3] Set("Local/hook@__func_periodic_hook_context__-000011c2;2", "GROUP(periodic-hook)=SIP/ATAxLA1-000006d02") in new stack
[Apr 14 22:15:51]     -- Executing [hook@__func_periodic_hook_context__:4] ExecIf("Local/hook@__func_periodic_hook_context__-000011c2;2", "0?Hangup()") in new stack
[Apr 14 22:15:51]     -- Executing [hook@__func_periodic_hook_context__:5] Set("Local/hook@__func_periodic_hook_context__-000011c2;2", "ChannelToSpy=SIP/ATAxLA1-000006d0") in new stack
[Apr 14 22:15:51]     -- Executing [hook@__func_periodic_hook_context__:6] ChanSpy("Local/hook@__func_periodic_hook_context__-000011c2;2", "SIP/ATAxLA1-000006d0,qEB") in new stack
[Apr 14 22:15:51]     -- Local/hook@__func_periodic_hook_context__-000011c2;1 answered
[Apr 14 22:15:51]     -- Executing [beep@__func_periodic_hook_context__:1] Answer("Local/hook@__func_periodic_hook_context__-000011c2;1", "") in new stack
[Apr 14 22:15:51]     -- Executing [beep@__func_periodic_hook_context__:2] Playback("Local/hook@__func_periodic_hook_context__-000011c2;1", "beep") in new stack
[Apr 14 22:15:51]     -- <Local/hook@__func_periodic_hook_context__-000011c2;1> Playing 'beep.ulaw' (language 'en')
[Apr 14 22:15:51]   == Spying on channel SIP/ATAxLA1-000006d0
[Apr 14 22:15:51]     -- Attaching spy channel Local/hook@__func_periodic_hook_context__-000011c2;2 to SIP/ATAxLA1-000006d0
[Apr 14 22:15:51]     -- Attaching spy channel Local/hook@__func_periodic_hook_context__-000011c2;2 to SIP/ATAxLA1-000006d0
{noformat}

The strange thing is that while this happens consistently on my Asterisk 18.3.0 both directly on a device channel (e.g. SIP/something) and on a Local channel, it does not on another 18.2.0 system if I add this on an incoming IAX2 call (in this case, neither issue occurs). I don't think this is related to the version but more likely some difference between the two environments that is causing such failures. As such, this may be hard to replicate, but I can provide debug logs if needed.
Comments:By: Asterisk Team (asteriskteam) 2021-04-14 21:41:54.727-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. Please note that log messages and other files should not be sent to the Sangoma Asterisk Team unless explicitly asked for. All files should be placed on this issue in a sanitized fashion as needed.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.

Please note that by submitting data, code, or documentation to Sangoma through JIRA, you accept the Terms of Use present at [https://www.asterisk.org/terms-of-use/|https://www.asterisk.org/terms-of-use/].
By: Joshua C. Colp (jcolp) 2021-04-15 03:44:53.578-0500

We require additional debug to continue with triage of your issue. Please follow the instructions on the wiki [1] for how to collect debugging information from Asterisk. For expediency, where possible, attach the debug with a '.txt' file extension so that the debug will be usable for further analysis.

Thanks!

[1] https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information


By: N A (InterLinked) 2021-04-15 07:47:20.929-0500

Attached is a debug of placing a call to another phone, picking up, saying hello to myself a few times, and hanging up. The debug starts right after I dial a code to enable MixMonitor for the call.
By: Joshua C. Colp (jcolp) 2021-04-15 08:05:09.012-0500

Do you have a log file of the working case? I think it may be timing specific where spying doesn't occur fast enough, so the beep gets done playing before.
By: N A (InterLinked) 2021-04-15 08:26:40.400-0500

Unfortunately, I have not been able to get it to work at all yet on my primary system, though I've tried a few different ways. I tried it on an older system that was upgraded to 18.2 a few months ago and it works perfectly there as I said on an inbound IAX2 call. But that's a different system, so there could be other variables in play. If a log file from the 18.2 would be helpful, such a call is attached, from around the time monitoring starts until after hangup. A few beeps are successfully heard on this call, and no fallthrough/timeout errors like on the other 18.3 system. (Just to be clear, I don't think it's the minute version difference to blame, just so happens they are slightly different here.)
By: Joshua C. Colp (jcolp) 2021-04-15 08:31:05.867-0500

Does this attached patch change anything?
By: N A (InterLinked) 2021-04-15 09:25:24.972-0500

No, unfortunately both issues persist as they did before.
By: Joshua C. Colp (jcolp) 2021-04-15 09:33:07.174-0500

Is it possible for you to get a packet capture of the SIP and RTP traffic for the device where the beep is being played to?
By: Joshua C. Colp (jcolp) 2021-04-15 09:33:24.095-0500

The output of "rtp set debug on" at the same time would also be useful for it.
By: N A (InterLinked) 2021-04-15 09:37:05.567-0500

I can take a packet capture from the Asterisk switch using tshark. I can't do it on my local network (which is remote from the Asterisk switch, in an entirely different state), because I don't have a managed switch that would allow me to do a network pcap. I could filter it to my IP and eliminate SSH and then send that to you privately if that would be helpful.

For rtp set debug on, would that go in the debug logs as well or do you just want what that will add to the CLI printout? Usually that spams the console when I turn it on.
By: Joshua C. Colp (jcolp) 2021-04-15 09:39:47.829-0500

I don't mind where it is taken from, as long as it includes the SIP and RTP traffic. As for "rtp set debug on" it goes to the CLI.
By: N A (InterLinked) 2021-04-15 11:06:53.096-0500

Is there a good secure way to send the packet capture to just you? That might be easier than trying to sanitize that without corrupting it.
I'll scrub the RTP debug and post that shortly.
By: N A (InterLinked) 2021-04-15 11:12:23.420-0500

Attached is the RTP debug from such a call, as well as all other CLI output.

I have the packet capture saved as well but not sure how to send that over.
By: Kevin Harwell (kharwell) 2021-04-15 11:29:04.557-0500

You can attach the packet capture to an email and send to asteriskteam@digium.com. Use the issue number as the subject.
By: Joshua C. Colp (jcolp) 2021-04-15 11:31:29.604-0500

Do note, however, that if such a thing would be useful to a community member who decides to look at this then they will not have access and if they require access, you will have to communicate with them.
By: N A (InterLinked) 2021-04-15 12:14:55.553-0500

That sounds fair, I just think it would be more valuable to provide you privately with unadulterated packets so you have all the context there available. Just sent it to the email above.
By: Joshua C. Colp (jcolp) 2021-04-15 12:27:56.319-0500

Is this SRTP?
By: Kevin Harwell (kharwell) 2021-04-15 12:33:55.232-0500

I just called the following dialplan:
{noformat}
exten => 960,1,NoOp()
same => n,Answer()
same => n,MixMonitor(/tmp/mixmonitor.wav,B(5))
same => n,Playback(demo-congrats)
same => n,Hangup()
{noformat}
from a pjsip endpoint, and did not hear any beep as well. During the call or in the recording. Also I saw the following log output on the CLI (slightly different from reported, but quite similar):
{noformat}
[Apr 15 12:25:01] WARNING[15524][C-00000002]: pbx.c:2927 pbx_extension_helper: No application 'ExecIf' for extension (__func_periodic_hook_context__, hook, 4)
[Apr 15 12:25:16] WARNING[15532][C-00000003]: pbx.c:2927 pbx_extension_helper: No application 'ExecIf' for extension (__func_periodic_hook_context__, hook, 4)
[Apr 15 12:25:31] WARNING[15554][C-00000004]: pbx.c:2927 pbx_extension_helper: No application 'ExecIf' for extension (__func_periodic_hook_context__, hook, 4)
{noformat}
This was against Asterisk 16, and no SRTP.

By: Joshua C. Colp (jcolp) 2021-04-15 12:36:33.749-0500

[~kharwell] Do you have the app_exec module loaded?
By: Kevin Harwell (kharwell) 2021-04-15 12:40:13.812-0500

Aah yeah that was it for me. I did not have _app_exec_ loaded. I can hear the beep now. However, it is not in the final recording, but not sure it's suppose to be.
By: Joshua C. Colp (jcolp) 2021-04-15 12:41:44.661-0500

Due to the placement of where the beep occurs, it does not occur in recordings.
By: N A (InterLinked) 2021-04-15 12:56:16.659-0500

I tried both from ATAs that were and were not using SRTP. I did not notice any ExecIf errors and I use ExecIf all the time in the dialplan. The capture I did was using SRTP I think.... do you need me to redo without it?
By: Joshua C. Colp (jcolp) 2021-04-15 13:00:12.665-0500

It's fine without, the "rtp set debug on" confirmed enough of things.
By: N A (InterLinked) 2021-04-17 20:39:12.442-0500

Another update:

It seems to work on certain incoming calls, where I do hear the beep now. It also seems like somehow there are 2 of them running in the background and that's why it's working:

[2021-04-17 21:35:39] WARNING[23503][C-00000d2d]: pbx.c:4576 __ast_pbx_run: Timeout, but no rule 't' or 'e' in context '__func_periodic_hook_context__'
[2021-04-17 21:35:39] WARNING[23504][C-00000d2f]: pbx.c:4576 __ast_pbx_run: Timeout, but no rule 't' or 'e' in context '__func_periodic_hook_context__'