AGI giving me result "510 Invalid or unknown command"?

Asterisk Asterisk Support
1

I’m upgrading a script that was working on 1.2.13 to run on a new system running 11.3.0

I’ve run into a strange problem.

In my php script that extensions.conf calls I set various variables so that I can GotoIf() based on various variable values when the php script returns, along with logging messages. Here are the lines of code in the php file:

$log->log("setting CHARTFOUND to 1", 1 );
execute_agi("SET VARIABLE CHARTFOUND 1");
$log->log("setting GREENWAYDOB to " . $result['dob'], 1 );
execute_agi("SET VARIABLE GREENWAYDOB ". $result['dob']);

first variable, CHARTFOUND, sets fine and I get this message in my logs:

2013-08-12T12:58:59-04:00 ALERT (1): setting CHARTFOUND to 1
2013-08-12T12:58:59-04:00 ALERT (1): execute_agi: executing SET VARIABLE CHARTFOUND 1
2013-08-12T12:58:59-04:00 ALERT (1): execute_agi: executing SET VARIABLE CHARTFOUND 1 - Done
2013-08-12T12:58:59-04:00 ALERT (1): execute_agi: result =  200 result=1

but setting the 2nd variable right after results in a 501

2013-08-12T12:58:59-04:00 ALERT (1): setting GREENWAYDOB to 2013-07-26
2013-08-12T12:58:59-04:00 ALERT (1): execute_agi: executing SET VARIABLE GREENWAYDOB 2013-07-26
2013-08-12T12:58:59-04:00 ALERT (1): execute_agi: executing SET VARIABLE GREENWAYDOB 2013-07-26 - Done
2013-08-12T12:58:59-04:00 ALERT (1): execute_agi: result =  [b]510 Invalid or unknown command[/b]

Here is the execute_agi() code:

function execute_agi($command) {
	GLOBAL $log, $parm_debug_on;
	$log->log("execute_agi: executing " . $command, 1);
	fwrite(STDOUT, "$command\n");
	fflush(STDOUT);
	$log->log("execute_agi: executing " . $command . ' - Done', 1);
	$result = trim(fgets(STDIN));
	$log->log("execute_agi: result =  " . $result, 1);
	$ret = array('code' => -1, 'result' => -1, 'timeout' => false, 'data' => '');
	if (preg_match("/^([0-9]{1,3}) (.*)/", $result, $matches)) {
		$ret['code'] = $matches[1];
		$ret['return'] = 0;
		if (preg_match('/^result=(0-9a-zA-Z]*\s?(?:\(?(.*?)\)?)?$/', $matches[2], $match)) {
			$ret['result'] = $match[1];
			$ret['timeout'] = ($match[2] === 'timeout') ? true:false;
			$ret['data'] = $match[2];
		}
	}
	$log->log("execute_agi: returning  " . print_r($ret), 1);
	return $ret;
}

It took me quite awhile to figure out that I was seeing 501 errors, but I’m baffled as to why or what I might be doing wrong that used to work in 1.2.13 that is causing problems in 11.3.0

I’m all out of magic, appreciate any help to get me steered in the right direction and get this problem behind me

2

I think I’ve solved this.

I’ve been running asterisk on the command line via “asterisk -cvvvvvvvvvvvvvvvvvvvvvvvvvvvvv”

This allows me to watch the script run and interact with the extensions.conf logic.

I turned on agi debugging via “agi set debug on” and saw more detail than I was logging on my own. Turns out that somehow the logging was sending an array back as a command (prob in return code I’m guessing) within execute_agi() since I was seeing:

<SIP/2001-00000002>AGI Rx << SET VARIABLE CHARTFOUND 1
<SIP/2001-00000002>AGI Tx >> 200 result=1
<SIP/2001-00000002>AGI Rx << Array
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx << (
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx <<     [code] => 200
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx <<     [result] => -1
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx <<     [timeout] =>
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx <<     [data] =>
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx <<     [return] => 0
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx << )
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx << SET VARIABLE GREENWAYDOB 2013-07-26
<SIP/2001-00000002>AGI Tx >> 200 result=1
<SIP/2001-00000002>AGI Rx << Array
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx << (
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx <<     [code] => 510
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx <<     [result] => -1
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx <<     [timeout] =>
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx <<     [data] =>
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx <<     [return] => 0
<SIP/2001-00000002>AGI Tx >> 510 Invalid or unknown command
<SIP/2001-00000002>AGI Rx << )

I can see that the actual SET VARIABLE was resulting in a “200 result=1”, but there was a rogue array being sent in and the result THAT was logged as the 510 from the attempt at running the array as some sort of Asterisk-like command. Screwy, but once I commented out the logging within the execute_agi() function then the CLI AGI debugging output shows that things are running correctly.