Asterisk 18.14.0 AGI lanch take more than 3 seconds intermitently druring 40 calls traffic

ntdon · March 17, 2023, 12:04pm

Hi Asterisk Experts,

AGI script take more than 3s to launch during high traffic (40 calls simultaneously)

The description is as below

Dial Plan: Having a AGI to count the channels in Asterisk
AGI call a API, API to count the channel and return the number of channels to AGI
Having script to send 40 calls to Asterisk
*Notes: Our Customer set the script to cancel the call if no response in 3 seconds

Results: 37 call passed, around 3 calls are failed intermittently (sometimes 40 calls passed)

We checked the asterisk log and found that some times, it take more than 3 seconds to launch and process the AGI.

Here is AGI log: As you can see below – API responded to AGI within miliseconds
2023-03-17 07:08:18,744 INFO 0312340038 channelCount.py 25 Start AGI script
2023-03-17 07:08:18,744 INFO 0312340038 channelCount.py 32 Request url: http://pbx3.collabosdev-internal.tokyo:80/api/v1/cpm/channels
2023-03-17 07:08:18,744 INFO 0312340038 channelCount.py 44 Request params: {‘TenantId’: 8001, ‘ProjectId’: 80011203}
2023-03-17 07:08:18,745 DEBUG 0312340038 channelCount.py 232 Starting new HTTP connection (1): pbx3.collabosdev-internal.tokyo:80
2023-03-17 07:08:18,772 DEBUG 0312340038 channelCount.py 465 http://pbx3.collabosdev-internal.tokyo:80 “POST /api/v1/cpm/channels HTTP/1.1” 200 77
2023-03-17 07:08:18,773 INFO 0312340038 channelCount.py 51 Status code: 200
2023-03-17 07:08:18,773 INFO 0312340038 channelCount.py 68 {‘ResultCode’: ‘0000’, ‘TenantChannelCounts’: 39, ‘ProjectChannelCounts’: 39}

Below is Asterisk console logs:
Please see the highlighed in bold below and AGI log above
You can see AGI started at 07:08:15 but AGI log above, it started at 07:08:18, 3 seconds later

Do we have any limitation with AGI ?
How to know whether this is a AGI issue or something else?

I attached the log for both case Failed and Passed, and also AGI script
Case Failed: here is the channel: provider_adjustone_0363390002-00000d5f –
Failed.txt (4.6 MB)
Case Passed: provider_adjustone_0363390002-00001c7c
Passed.txt (4.8 MB)
AGI script: channelCount.txt (2.5 KB)

Any advice/solution you could provide would be high appricated

*Notes: we are using VM with 32G RAM and 4CPU, we monitored the asterisk RAM and CPU

[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_request: /var/lib/asterisk/agi-bin/pyst2/channelCount.py
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_channel: PJSIP/provider_adjustone_0363390002-00000d5f
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_language: en
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_type: PJSIP
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_uniqueid: 1679036895.3641
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_version: 18.14.0
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_callerid: 0312340038
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_calleridname: unknown
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_callingpres: 0
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_callingani2: 0
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_callington: 0
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_callingtns: 0
[Mar 17 07:08:15] DEBUG[9324] manager.c: Examining AMI event:

[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_dnid: 0363390002
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_rdnis: unknown
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_context: from-trunk
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_extension: 8001202_0
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_priority: 2
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_enhanced: 0.0
*[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_accountcode: *
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_threadid: 139984879376128
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_arg_1: 80011203
[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> agi_arg_2: 8001
*[Mar 17 07:08:15] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> *

||Line 159141: [Mar 17 07:08:18] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Rx << VERBOSE {‘ResultCode’: ‘0000’, ‘TenantChannelCounts’: 39, ‘ProjectChannelCounts’: 39} 1|
|—|—|
||Line 159143: [Mar 17 07:08:18] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> 200 result=1|

||Line 160064: [Mar 17 07:08:18] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Rx << VERBOSE Normalty 1|
|—|—|
||Line 160066: [Mar 17 07:08:18] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> 200 result=1|

||Line 160987: [Mar 17 07:08:18] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Rx << SET VARIABLE number_active_channels_tenant 39|
|—|—|
||Line 160988: [Mar 17 07:08:18] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Tx >> 200 result=1|

||Line 162844: [Mar 17 07:08:18] DEBUG[29472][C-00000c63] res_agi.c: PJSIP/provider_adjustone_0363390002-00000d5f hungup|
|—|—|
||Line 163493: [Mar 17 07:08:18] VERBOSE[29472][C-00000c63] res_agi.c: <PJSIP/provider_adjustone_0363390002-00000d5f>AGI Script /var/lib/asterisk/agi-bin/pyst2/channelCount.py completed, returning 4|

jcolp · March 17, 2023, 12:08pm

In order to execute a script, process, anything, Asterisk uses the mechanisms provided by the operating system. Depending on system usage and memory usage this can take a period of time, and can even have an impact on conference bridges. It is recommended to use FastAGI instead as that removes the need to execute a script.

jcolp · March 17, 2023, 12:09pm

FreePBX added support for using FastAGI for the conference bridge reason, in fact: Performance Improvements in FreePBX | FreePBX - Let Freedom Ring

ntdon · March 18, 2023, 11:18am

Dear @jcolp ,
Thank you very much for your response,

If so, should we setup Fast AGI server at the local or we need a remote server ?
I mean if I keep the Fast AGI server script at local, do you know if the Fast AGI performance is better than AGI?

By the way, I looked around and see different instruction for setting up Fast AGI
Not sure I would use the tip below – or you have any advice or links or document which you can help to share with me for reference ?

Thanks again for all your help

david551 · March 18, 2023, 11:39am

I would make it local, unless the server is doing something expensive, itself.

Launching a python interpreter and pre-processing a script is always going to be much more expensive than reading a TCP message, and possibly forking a new thread.

jcolp · March 18, 2023, 6:20pm

I have no experience with Python FastAGI so can’t comment on that.

ntdon · March 20, 2023, 10:12am

Many thanks @david551 and @jcolp for your reply,

We build and run test.py with python3 as FastAGI server script as below (python2 works well but we need to run with python3
FastAGIServer.txt (1.2 KB)

AGI command “agi.verbose/ agi.set” got an error “a bytes-like object is required, not ‘str’”
See the detail in Failed_console.txt (2.3 KB)

It seems that there is an issue in source code

def send_command(self, command, *args):
    """Send a command to Asterisk"""
    command = command.strip()
    command = '%s %s' % (command, ' '.join(map(str, args)))
    command = command.strip()
    if command[-1] != '\n':
        command += '\n'
    self.stderr.write('    COMMAND: %s' % command)
    self.stdout.write(command)
    self.stdout.flush()

We changed self.stdout.write(command) → self.stdout.write(command.encode()) – Then the issue is resolved.

Do you think you need to provide a fix to asterisk source code for this issue ?

In the meantime, Do you have any idea/advice for us to resolve this issue on our lab ?

*Note: Our Customer don’t want to edit Asterisk source code by ourself
Here is reference for asterisk source code, it is same as in our asterisk pyst2/agi.py at master · jfernandz/pyst2 · GitHub

david551 · March 20, 2023, 10:48am

That’s not Asterisk source code; it is third party code, and it isn’t actually part of Asterisk, but rather an AGI class library.

ldo · March 20, 2023, 9:15pm

I had a look at the source code for pyst2. It uses threading, which is not bad in itself, but the number of threads needed to manage a single manager connection seems a bit excessive. I counted three: there are initially the message_thread and event_dispatch_thread, and then the message_thread action spawns another thread to run _receive_data. And with all this mechanism, it doesn’t actually support non-blocking requests.

ntdon · March 24, 2023, 11:13am

Thanks all your support, we have used another library “panoramisk”
And FastAGI works well with python3 now – Please be informed

root@ip-172-31-15-204:/var/lib/asterisk/agi-bin/pyst2# cat fastagi_server.py
import os
import asyncio
from panoramisk import fast_agi
import logger
import logging
from channelCount import channel_count
from incomingcallcount_fastagi import incomingcall_count

file_name=os.path.basename(file)
get_log = logger.fast_agi_get(file_name)
LOG = logging.LoggerAdapter(get_log, {‘caller_id’: None})

async def main():
fa_app = fast_agi.Application()
fa_app.add_route(‘channel-count’, channel_count)
fa_app.add_route(‘incomingcall-count’, incomingcall_count)
server = await asyncio.start_server(fa_app.handler, ‘127.0.0.1’, 4573)
LOG.info('message: ’ + ‘Serving on {}’.format(server.sockets[0].getsockname()))
try:
await server.serve_forever()
except KeyboardInterrupt as err:
LOG.error({‘message’: str(err)})
finally:
# Close the server
LOG.info({‘message’: ‘Close the server’})
server.close()

if name == ‘main’:
asyncio.run(main())

ldo · March 25, 2023, 7:52am

This is another reason why I put #end lines in my Python code–because if you lose the significant whitespace, your code turns into complete gibberish, and without such hints, it is just about impossible to reconstruct the correct indentation.

Python is a terrific language, that lets you achieve powerful things very elegantly, and I know GvR has said that beginners found it easier to cope with indentation than explicit statement brackets. Still, I think this particular design feature was a mistake.

david551 · March 25, 2023, 11:27am

The other thing to learn is always mark up code and logs as pre-formatted, when using the forum:

root@ip-172-31-15-204:/var/lib/asterisk/agi-bin/pyst2# cat fastagi_server.py
import os
import asyncio
from panoramisk import fast_agi
import logger
import logging
from channelCount import channel_count
from incomingcallcount_fastagi import incomingcall_count

file_name=os.path.basename(__file__)
get_log = logger.fast_agi_get(file_name)
LOG = logging.LoggerAdapter(get_log, {'caller_id': None})

async def main():
    fa_app = fast_agi.Application()
    fa_app.add_route('channel-count', channel_count)
    fa_app.add_route('incomingcall-count', incomingcall_count)
    server = await asyncio.start_server(fa_app.handler, '127.0.0.1', 4573)
    LOG.info('message: ' +  'Serving on {}'.format(server.sockets[0].getsockname()))
    try:
        await server.serve_forever()
    except KeyboardInterrupt as err:
        LOG.error({'message': str(err)})
    finally:
        # Close the server
        LOG.info({'message': 'Close the server'})
        server.close()

if __name__ == '__main__':
    asyncio.run(main())