| Summary: | ASTERISK-27610: app_amd.so returning TOOLONG before reaching the timeout | ||||
| Reporter: | Michael Cargile (mcargile) | Labels: | patch | ||
| Date Opened: | 2018-01-22 11:54:07.000-0600 | Date Closed: | 2018-03-07 15:47:12.000-0600 | ||
| Priority: | Major | Regression? | |||
| Status: | Closed/Complete | Components: | Applications/app_amd | ||
| Versions: | 13.17.2 | Frequency of Occurrence | |||
| Related Issues: |
| ||||
| Environment: | Vicidial dial server running OpenSuSE 42.1 on Intel hardware | Attachments: | ( 0) agi_explainations.txt ( 1) amd_v2.patch ( 2) amd.patch ( 3) cli.txt ( 4) dialplan.txt ( 5) manager_events.txt | ||
| Description: | Calls that pass through AMD are returning TOOLONG about 70% of the time even though they have not reached the analysis timeout. Here is an example:
{noformat} [Jan 18 12:44:12] -- Executing [8369@default:2] AMD("SIP/sgw2-00000007", "2000,2000,1000,5000,120,50,4,256") in new stack [Jan 18 12:44:12] -- AMD: SIP/sgw2-00000007 (N/A) (N/A) (Fmt: slin) [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Changed state to STATE_IN_SILENCE [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Short Word Duration: 20 [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Short Word Duration: 40 [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Short Word Duration: 40 [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Detected Talk, previous silence duration: 100 [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Short Word Duration: 20 [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Detected Talk, previous silence duration: 100 [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Short Word Duration: 20 [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Detected Talk, previous silence duration: 100 [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Short Word Duration: 20 [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Detected Talk, previous silence duration: 100 [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Short Word Duration: 20 [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Detected Talk, previous silence duration: 100 [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Short Word Duration: 20 [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Detected Talk, previous silence duration: 200 [Jan 18 12:44:12] -- AMD: Channel [SIP/sgw2-00000007]. Short Word Duration: 20 [Jan 18 12:44:13] -- AMD: Channel [SIP/sgw2-00000007]. Too long... {noformat} TotalAnalysis is set to 5000 or 5 seconds and yet according to the CLI at most 2 seconds has elapsed since the AMD app was initiated. I ran tests on both Asterisk 11 and Asterisk 13 comparing the results. I had two Vicidial servers setup. One with 11 the other with 13. I had them calling into two different IVRs. The first IVR played an audio file that was just saying "Hello". The second IVR played an audio file that sounded like your typical answering machine message, "Hello. You have reached the blah residence. Please leave a messsage." Neither audio file was over 3 seconds long. I then called each number 50k times from both dialers. So each dialer placed a total of 100k calls. Asterisk 11 only had 123 TOOLONG messages most likely from poor audio connection. Asterisk 13 on the other hand had 70k+ TOOLONGs. Also the results for the non-TOOLONG calls on Asterisk 13 were very poor. It only seems to be about 50% accurate at determining if the audio is the answering machine message or just "hello". My guess is that it is basically randomly selecting one, but that is hard to say. From what I can tell from the code not much has changed in app_amd from Asterisk 11 to Asterisk 13. My guess is some core resource it relies on for timing has changed and it was not adjusted accordingly. I will attached details on how to reproduce this in the comments. | ||||
| Comments: | By: Asterisk Team (asteriskteam) 2018-01-22 11:54:08.299-0600 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. 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]. By: Michael Cargile (mcargile) 2018-01-22 12:15:35.235-0600 dialplan.txt is the dialplan from the Asterisk 13 server used in my testing. manager_events.txt are the two manager events that were run for this call. agi_explanations.txt are brief explanations of the AGI scripts you will see in the dialplan and CLI output. cli.txt is the CLI output for the example call. AMD for the call in question exited in less than a second dispite totalAnalysis set to 5000. By: George Joseph (gjoseph) 2018-01-22 14:13:11.781-0600 Hi Michael, Are you compiling Asterisk yourself for using distribution packages? Had you been running earlier versions of 13 without issue or did you go directly from 11 to 13.17.2? You're correct in that nothings changed in app_amd for a while December of 2015) but could you try 13.19.0 just for the heck of it? By: Michael Cargile (mcargile) 2018-01-22 16:22:17.709-0600 It is a version pulled from OpenSuSE's open build service. My colleague actually maintains it. I have not tried it on earlier versions of 13. I will see about getting a 13.19.0 version built and tested. By: George Joseph (gjoseph) 2018-01-23 08:15:46.328-0600 Thanks, let us know. By: Michael Cargile (mcargile) 2018-01-25 12:02:03.288-0600 Still doing it. {code} [Jan 25 13:00:06] -- Executing [8369@default:2] AMD("SIP/sgw2-0000000f", "2000,2000,1000,5000,120,50,4,256") in new stack [Jan 25 13:00:06] -- AMD: SIP/sgw2-0000000f (N/A) (N/A) (Fmt: slin) [Jan 25 13:00:06] -- AMD: initialSilence [2000] greeting [2000] afterGreetingSilence [1000] totalAnalysisTime [5000] minimumWordLength [120] betweenWordsSilence [50] maximumNumberOfWords [4] silenceThreshold [256] maximumWordLength [5000] [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Short Word Duration: 40 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Short Word Duration: 20 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Short Word Duration: 20 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Short Word Duration: 20 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Detected Talk, previous silence duration: 100 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Short Word Duration: 20 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Detected Talk, previous silence duration: 200 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Short Word Duration: 20 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Detected Talk, previous silence duration: 100 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Short Word Duration: 20 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Detected Talk, previous silence duration: 100 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Short Word Duration: 20 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Detected Talk, previous silence duration: 100 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Short Word Duration: 20 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Detected Talk, previous silence duration: 100 [Jan 25 13:00:06] -- AMD: Channel [SIP/sgw2-0000000f]. Short Word Duration: 40 [Jan 25 13:00:07] -- AMD: Channel [SIP/sgw2-0000000f]. Too long... {code} By: Michael Cargile (mcargile) 2018-01-30 12:49:22.572-0600 I added this debug line to app_amd.c right after the framelength variable is calculated and I think I see what is causing this, just not sure how to fix it: {code}ast_debug(1, "AMD: Channel [%s] iTotalTime [%d] framelength [%d] totalAnalysisTime [%d]\n", ast_channel_name(chan), iTotalTime, framelength, totalAnalysisTime );{code} Here is a run through with the debug: {code} [Jan 30 13:34:24] -- Executing [8369@default:3] AMD("SIP/dev2-0000003b", "2000,2000,1000,5000,120,50,4,256") in new stack [Jan 30 13:34:24] -- AMD: SIP/dev2-0000003b (N/A) (N/A) (Fmt: slin) [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [0] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Changed state to STATE_IN_SILENCE [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [100] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [200] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [300] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [400] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [500] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [600] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [620] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [720] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [740] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [840] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [860] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [960] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [980] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1080] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1100] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1200] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1220] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1320] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1340] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1440] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1460] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1560] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1580] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1680] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1700] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1800] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1820] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1920] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [1940] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2040] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2060] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2160] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2180] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2280] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2300] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2400] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2420] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2520] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2540] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2640] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2660] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2760] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2780] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2880] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [2900] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3000] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3020] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3120] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3140] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3240] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3260] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3360] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3380] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3480] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3500] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3600] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3620] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3720] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3740] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3840] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3860] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3960] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [3980] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4080] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4100] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4200] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:24] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4220] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:24] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:25] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4320] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:25] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:25] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4340] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:25] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:25] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4440] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:25] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:25] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4460] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:25] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:25] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4560] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:25] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:25] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4580] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:25] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:25] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4680] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:25] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:25] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4700] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:25] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:25] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4800] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:25] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:25] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4820] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:25] -- AMD: Channel [SIP/dev2-0000003b]. Short Word Duration: 20 [Jan 30 13:34:25] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4920] framelength [20] totalAnalysisTime [5000] [Jan 30 13:34:25] -- AMD: Channel [SIP/dev2-0000003b]. Detected Talk, previous silence duration: 100 [Jan 30 13:34:25] DEBUG[18657][C-00000051]: app_amd.c:300 isAnsweringMachine: AMD: Channel [SIP/dev2-0000003b] iTotalTime [4940] framelength [100] totalAnalysisTime [5000] [Jan 30 13:34:25] -- AMD: Channel [SIP/dev2-0000003b]. Too long... {code} It looks like the framelength is not getting calculated correctly. Here is the code that does that: {code} /* If the total time exceeds the analysis time then give up as we are not too sure */ if (f->frametype == AST_FRAME_VOICE) { framelength = (ast_codec_samples_count(f) / DEFAULT_SAMPLES_PER_MS); } else { framelength = 2 * maxWaitTimeForFrame; } {code} No clue how it is supposed to work. By: Michael Cargile (mcargile) 2018-02-01 20:55:47.567-0600 So I am pretty sure I figured out what is happening. I changed my debug output to this: {code} if ( f->frametype == AST_FRAME_VOICE ) { ast_debug(1, "AMD: Channel [%s] frametype [AST_FRAME_VOICE] iTotalTime [%d] framelength [%d] totalAnalysisTime [%d]\n", ast_channel_name(chan), iTotalTime, f->len, totalAnalysisTime ); } else if ( f->frametype == AST_FRAME_NULL ) { ast_debug(1, "AMD: Channel [%s] frametype [AST_FRAME_NULL] iTotalTime [%d] framelength [%d] totalAnalysisTime [%d]\n", ast_channel_name(chan), iTotalTime, f->len, totalAnalysisTime ); } else if ( f->frametype == AST_FRAME_CNG ) { ast_debug(1, "AMD: Channel [%s] frametype [AST_FRAME_CNG] iTotalTime [%d] framelength [%d] totalAnalysisTime [%d]\n", ast_channel_name(chan), iTotalTime, f->len, totalAnalysisTime ); } {code} What I found was that for every voice frame app_amd.c processed it was also getting a null frame. Not sure why that is. I will leave that up so someone who understands this code a bit better to figure out. Those null frames were being counted as 100ms even though they were 0ms. Upon digging a bit more I also found that the ast_frame struct has a len variable in it that is the length in ms of the frame. I am assuming that when app_amd.c was written that was not there. So I have written a patch that seems to have fixed the issue. I am running an extensive test of it and will let you know the results. By: Michael Cargile (mcargile) 2018-02-05 16:52:58.841-0600 Okay something still is not right. When I call through SIP this patch seems to work (though I am not positive). However if I call through IAX this patch does not work at all. All the frames are NULL and the f->len is always 0. I am at a loss. By: Michael Cargile (mcargile) 2018-02-06 09:37:02.045-0600 So I think I figured out what is actually going on. ast_waitfor is returning after only a few milliseconds at times. When it does ast_read returns a NULL frame because the ast_waitfor did not wait long enough for a frame to even come in. With SIP channels this seems to be happening about once every other call to ast_waitfor. With IAX2 channels this seems to be happening multiple times in a row. The documentation for ast_read suggests that if you get a NULL frame you should assume the channel is disconnected. That is clearly not the case though as the code is getting VOICE frames interspersed with the NULL frames. Not sure if that documentation of ast_read needs updating or not. I have modified the detection code to ignore the NULL frames. I added a count of the NULL frames. If the NULL frame count gets over 20 in a row then it will treat the channel as if it disconnected. I also changed it so that the framelength for non-VOICE frames is based off the number of ms ast_waitfor waited rather than the max amount of time it was told to wait. These changes seem to make it work much better. I am running another extended test of my code, but this seems to have fixed the issue for both SIP and IAX calls. By: Joshua C. Colp (jcolp) 2018-02-06 09:40:44.447-0600 The comment for ast_read is a bit unclear. It's referring to if ast_read returns NULL, that is no frame is returned at all. Returning a frame that is of type NULL is different and should be ignored. By: Michael Cargile (mcargile) 2018-02-06 11:59:34.015-0600 Ahh see that makes much more sense. I was assuming that it meant it was referring to AST_FRAME_NULL in that comment not specifically a NULL value. Now the question is why was app_amd.c treating AST_FRAME_NULL as silence to begin with and why was that working from Asterisk 1.4 all the way till Asterisk 11 (possibly even in Asterisk 12). I am guessing that was a mistake by the original developers and it just did not matter much as very few frames of type AST_FRAME_NULL were being returned. Now it is getting far more AST_FRAME_NULL. I am modifying my code to completely ignore AST_FRAME_NULL frames. The next question I have is {code}frameLength = (ast_codec_samples_count(f) / DEFAULT_SAMPLES_PER_MS);{code} still the correct way to measure the length of a voice frame. I tried using f->len which seems valid on SIP channels, but on some IAX channel that is 0. By: Richard Mudgett (rmudgett) 2018-02-07 13:07:43.563-0600 For AMD that is an acceptable way to calculate the frame length in ms because the read format is always going to be slin. The AMD application sets the channel's read format to ast_format_slin before going into the ast_waitfor() loop so the DSP code can process the audio signal. By: Michael Cargile (mcargile) 2018-02-07 15:42:54.381-0600 Excellent. My current code has proven stable (placed 100k test calls to recordings and Asterisk never crashed). I am getting ready to do a live test to verify that functionality has been properly restored. I will upload the new patch after I have verified the functionality. By: Michael Cargile (mcargile) 2018-02-13 16:33:58.004-0600 Patch is stable and is giving much better results than the stock app_amd.c. I am not entirely sure that the issue is completely fixed, but it is definitely better than before. By: Richard Mudgett (rmudgett) 2018-02-13 16:38:13.683-0600 Thanks for the contribution! If you'd like your contribution to be included faster, you should submit your patch for code review by the Asterisk Developer Community. To do so, please follow the Code Review [1] instructions on the wiki. Be sure to: * Verify that your patch conforms to the Coding Guidelines [2] * Review the Code Review Checklist [3] for common items reviewers will look for * If necessary, provide tests for the Asterisk Test Suite that verify the correctness of your patch [4] When ready, submit your patch and any tests to Gerrit [5] for code review. Thanks! [1] https://wiki.asterisk.org/wiki/display/AST/Code+Review [2] https://wiki.asterisk.org/wiki/display/AST/Coding+Guidelines [3] https://wiki.asterisk.org/wiki/display/AST/Code+Review+Checklist [4] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Test+Suite+Documentation [5] https://wiki.asterisk.org/wiki/display/AST/Gerrit+Usage By: Michael Cargile (mcargile) 2018-02-23 21:47:36.598-0600 Just submitted to this to Gerrit. I think I did it correctly. By: Friendly Automation (friendly-automation) 2018-03-07 13:56:59.725-0600 Change 8389 merged by Jenkins2: apps/app_amd.c: Fixed total time and silence calculations [https://gerrit.asterisk.org/8389|https://gerrit.asterisk.org/8389] By: Friendly Automation (friendly-automation) 2018-03-07 14:01:00.069-0600 Change 8392 merged by Jenkins2: apps/app_amd.c: Fixed total time and silence calculations [https://gerrit.asterisk.org/8392|https://gerrit.asterisk.org/8392] By: Friendly Automation (friendly-automation) 2018-03-07 14:07:17.226-0600 Change 8391 merged by Jenkins2: apps/app_amd.c: Fixed total time and silence calculations [https://gerrit.asterisk.org/8391|https://gerrit.asterisk.org/8391] By: Abhay Gupta (agupta) 2018-10-31 07:25:21.687-0500 There is a issue that looks with the patch . It waits for the frame to update time and if no packet is received it waits till the rtp_timeout and call is dropped without AMD ever coming out and analysis time completed . By: Abhay Gupta (agupta) 2018-10-31 07:28:23.251-0500 AMD application called at 13:49:09 and Hangup 13:49:50 with causecode 44 which comes when retp_timeout occurs . AMD: initialSilence [5500] greeting [1500] afterGreetingSilence [800] totalAnalysisTime [8000] minimumWordLength [130] betweenWordsSilence [50] maximumNumberOfWords [5] silenceThreshold [256] maximumWordLength [5000] T 2018/10/29 13:49:09.669772 139.99.122.35:5038 -> 139.99.122.35:39894 [AP] Event: Newexten. Privilege: call,all. Channel: PJSIP/bluefive-00004c59. ChannelState: 6. ChannelStateDesc: Up. CallerIDNum: 442037752312. CallerIDName: 442037752312. ConnectedLineNum: 442037752312. ConnectedLineName: 442037752312. Language: en. AccountCode: AD102920181348469468. Context: 1. Exten: dialer. Priority: 2. Uniqueid: 1540820927.32814. Linkedid: 1540820927.32814. Extension: dialer. Application: AMD. AppData: . . T 2018/10/29 13:49:50.172609 139.99.122.35:5038 -> 139.99.122.35:39894 [AP] Event: Hangup. Privilege: call,all. Channel: PJSIP/bluefive-00004c59. ChannelState: 6. ChannelStateDesc: Up. CallerIDNum: 442037752312. CallerIDName: 442037752312. ConnectedLineNum: 442037752312. ConnectedLineName: 442037752312. Language: en. AccountCode: AD102920181348469468. Context: 1. Exten: dialer. Priority: 2. Uniqueid: 1540820927.32814. Linkedid: 1540820927.32814. Cause: 44. Cause-txt: Requested channel not available. By: Richard Mudgett (rmudgett) 2018-10-31 07:34:09.536-0500 [~alex.guppy18@gmail.com] Please create a new issue and reference this issue rather than commenting on a CLOSED issue. Remember that app_amd is extended support and is community supported so any fix will have to come from the community. By: Joshua C. Colp (jcolp) 2018-11-26 08:54:16.504-0600 [~mcargile] A review has been up at https://gerrit.asterisk.org/#/c/asterisk/+/10707/ which alters things further. Can you take a gander and provide some input? | ||||