[asterisk-bugs] [JIRA] (ASTERISK-27610) app_amd.so returning TOOLONG before reaching the timeout

[Michael Cargile (JIRA)]

    [ https://issues.asterisk.org/jira/browse/ASTERISK-27610?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=242034#comment-242034 ] 

Michael Cargile commented on ASTERISK-27610:
--------------------------------------------

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.

> app_amd.so returning TOOLONG before reaching the timeout
> --------------------------------------------------------
>
>                 Key: ASTERISK-27610
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-27610
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Applications/app_amd
>    Affects Versions: 13.17.2
>         Environment: Vicidial dial server running OpenSuSE 42.1 on Intel hardware
>            Reporter: Michael Cargile
>            Assignee: Unassigned
>              Labels: patch
>         Attachments: agi_explainations.txt, amd.patch, cli.txt, dialplan.txt, manager_events.txt
>
>
> 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 at 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.



--
This message was sent by Atlassian JIRA
(v6.2#6252)