After 25~27 concurrent calls, php agi didn't work properly

Hi :smiley:

We have outbound service that play voice message to end-user.

The below php source is to EXEC dial. After 25~27 concurrent calls, php agi didn’t work properly.I couldn’t see debug logs. :cry:

 function rate_engine_performcall ($agi, $trumpia, $proxy="innodial"){

                $dialstr = "SIP/$trumpia->destination@" . $proxy;

                $trumpia -> debug( VERBOSE | WRITELOG, $agi, __FILE__, __LINE__, "Start $agi->exec(Dial $dialstr|60) xxxxx");

                $myres = $agi->exec("Dial $dialstr|60");

                $trumpia -> debug( VERBOSE | WRITELOG, $agi, __FILE__, __LINE__, "End $agi->exec(Dial $dialstr|60) xxxxx");

                $answeredtime = $agi->get_variable("ANSWEREDTIME");
                $this->answeredtime = $answeredtime['data'];            
                $dialstatus = $agi->get_variable("DIALSTATUS");
                $this->dialstatus = $dialstatus['data'];

                $trumpia -> debug( VERBOSE | WRITELOG, $agi, __FILE__, __LINE__, "dial status : " . $this->dialstatus);

- success log

[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << VERBOSE "file:sm_dial.php - line:60 - GET VARIABLE : CALLEDP=1 | CALLED=5xxxxxxxxx | CALLERID=51xxxxxxxx | CBID=1-1005529680 | INTRO=d/ddiemer/138124718774_Record_intro-10-08-2013[08_46] | MSG=d/ddiemer/138124726238_Record_message-10-08-2013[08_47] | VOICE=0 | MODE=live | SENDTASKUID=3-1-1005529680" 1
[Oct  8 09:02:05] VERBOSE[29268] logger.c:   sm_dial.php: file:sm_dial.php - line:60 - GET VARIABLE : CALLEDP=1 | CALLED=5xxxxxxxxx | CALLERID=51xxxxxxxx | CBID=1-1005529680 | INTRO=d/ddiemer/138124718774_Record_intro-10-08-2013[08_46] | MSG=d/ddiemer/138124726238_Record_message-10-08-2013[08_47] | VOICE=0 | MODE=live | SENDTASKUID=3-1-1005529680
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=1
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << VERBOSE "file:sm_dial.php - line:66 - Destination >>>>>>>>> 15xxxxxxxxx" 1
[Oct  8 09:02:05] VERBOSE[29268] logger.c:   sm_dial.php: file:sm_dial.php - line:66 - Destination >>>>>>>>> 15xxxxxxxxx
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=1
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << EXEC SIPAddHeader X-Asterisk-callerid:5xxxxxxxx
[Oct  8 09:02:05] VERBOSE[29268] logger.c:     -- AGI Script Executing Application: (SIPAddHeader) Options: (X-Asterisk-callerid:51xxxxxxxx)
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=0
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << EXEC SIPAddHeader X-Asterisk-sendtaskuid:3-1-1005529680
[Oct  8 09:02:05] VERBOSE[29268] logger.c:     -- AGI Script Executing Application: (SIPAddHeader) Options: (X-Asterisk-sendtaskuid:3-1-1005529680)
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=0
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << SET CALLERID 10479635
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=1
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << VERBOSE "file:sm_dial.php - line:76 - Request >>>>>>>>> http://api.trumpia.com:8658/rest/biz/voice/send_voice_log/callresult?sendtask_uid=1005529680&received_status=1 >>>>>>>>>>>> HTTP/1.1 200 OK" 1
[Oct  8 09:02:05] VERBOSE[29268] logger.c:   sm_dial.php: file:sm_dial.php - line:76 - Request >>>>>>>>> http://api.trumpia.com:8658/rest/biz/voice/send_voice_log/callresult?sendtask_uid=1005529680&received_status=1 >>>>>>>>>>>> HTTP/1.1 200 OK
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=1
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << VERBOSE "" 1
[Oct  8 09:02:05] VERBOSE[29268] logger.c:   sm_dial.php: 
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=1
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << VERBOSE "" 1
[Oct  8 09:02:05] VERBOSE[29268] logger.c:   sm_dial.php: 
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=1
[b][Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << VERBOSE "file:class.rateengine.php - line:24 - Start (Dial SIP/15xxxxxxxx@innodial|60) xxxxx" 1
[Oct  8 09:02:05] VERBOSE[29268] logger.c:   sm_dial.php: file:class.rateengine.php - line:24 - Start (Dial SIP/15xxxxxxxxx@innodial|60) xxxxx[/b]
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=1
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << EXEC Dial SIP/15xxxxxxxxx@innodial|60
[Oct  8 09:02:05] VERBOSE[29268] logger.c:     -- AGI Script Executing Application: (Dial) Options: (SIP/15xxxxxxxxx@innodial|60)
[Oct  8 09:02:05] VERBOSE[29268] logger.c:     -- Called 15xxxxxxxxx@innodial
[Oct  8 09:02:06] VERBOSE[29270] logger.c:   == Parsing '/etc/asterisk/manager.conf': [Oct  8 09:02:06] VERBOSE[29270] logger.c: Found
[Oct  8 09:02:06] VERBOSE[29270] logger.c:   == Manager 'trumpia' logged on from 127.0.0.1
[Oct  8 09:02:06] VERBOSE[29270] logger.c:   == Manager 'trumpia' logged off from 127.0.0.1
[Oct  8 09:02:06] VERBOSE[29272] logger.c:     -- Executing [s@trumpia-sendmessage:1] AGI("Local/s@trumpia-sendmessage-fb06,2", "sm_dial.php") in new stack
[Oct  8 09:02:06] VERBOSE[29272] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/sm_dial.php

- Fail log.

[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << VERBOSE "file:sm_dial.php - line:60 - GET VARIABLE : CALLEDP=1 | CALLED=5xxxxxxxxx | CALLERID=51xxxxxxxx | CBID=1-1005529680 | INTRO=d/ddiemer/138124718774_Record_intro-10-08-2013[08_46] | MSG=d/ddiemer/138124726238_Record_message-10-08-2013[08_47] | VOICE=0 | MODE=live | SENDTASKUID=3-1-1005529680" 1
[Oct  8 09:02:05] VERBOSE[29268] logger.c:   sm_dial.php: file:sm_dial.php - line:60 - GET VARIABLE : CALLEDP=1 | CALLED=5xxxxxxxxx | CALLERID=51xxxxxxxx | CBID=1-1005529680 | INTRO=d/ddiemer/138124718774_Record_intro-10-08-2013[08_46] | MSG=d/ddiemer/138124726238_Record_message-10-08-2013[08_47] | VOICE=0 | MODE=live | SENDTASKUID=3-1-1005529680
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=1
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << VERBOSE "file:sm_dial.php - line:66 - Destination >>>>>>>>> 15xxxxxxxxx" 1
[Oct  8 09:02:05] VERBOSE[29268] logger.c:   sm_dial.php: file:sm_dial.php - line:66 - Destination >>>>>>>>> 15xxxxxxxxx
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=1
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << EXEC SIPAddHeader X-Asterisk-callerid:5xxxxxxxx
[Oct  8 09:02:05] VERBOSE[29268] logger.c:     -- AGI Script Executing Application: (SIPAddHeader) Options: (X-Asterisk-callerid:51xxxxxxxx)
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=0
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << EXEC SIPAddHeader X-Asterisk-sendtaskuid:3-1-1005529680
[Oct  8 09:02:05] VERBOSE[29268] logger.c:     -- AGI Script Executing Application: (SIPAddHeader) Options: (X-Asterisk-sendtaskuid:3-1-1005529680)
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=0
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << SET CALLERID 10479635
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=1
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << VERBOSE "file:sm_dial.php - line:76 - Request >>>>>>>>> http://api.trumpia.com:8658/rest/biz/voice/send_voice_log/callresult?sendtask_uid=1005529680&received_status=1 >>>>>>>>>>>> HTTP/1.1 200 OK" 1
[Oct  8 09:02:05] VERBOSE[29268] logger.c:   sm_dial.php: file:sm_dial.php - line:76 - Request >>>>>>>>> http://api.trumpia.com:8658/rest/biz/voice/send_voice_log/callresult?sendtask_uid=1005529680&received_status=1 >>>>>>>>>>>> HTTP/1.1 200 OK
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=1
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << VERBOSE "" 1
[Oct  8 09:02:05] VERBOSE[29268] logger.c:   sm_dial.php: 
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=1
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Rx << VERBOSE "" 1
[Oct  8 09:02:05] VERBOSE[29268] logger.c:   sm_dial.php: 
[Oct  8 09:02:05] VERBOSE[29268] logger.c: AGI Tx >> 200 result=1

[b]- I monitored and logged asterisk event and sip call id.
I couldn’t see any dial event when failed.

  • I monitored sar, enough memory and cpu. lower than 2~3% used.
  • Asterisk version 1.4 / phpagi version 2.0

When this happened?? Asterisk has limited option?
How to solve this problem?[/b]