Logon Credentials Issue with dialparties.agi

bmcglynn · October 8, 2008, 1:09pm

Hi,

I upgraded a 2.4 installation of FreePBX to 2.5 using the upgrade scripts and am having an issue now with the extensions ringing.

On our PBX, we have 2 direct dial ins and 1 IVR. The IVR is working well, although when you dial an extension it will pause for 20-30 seconds before ringing an extension. Likewise if you try to dial from one extension to another, it can take 20-30 seconds.

In the case where a DID is connected directly to an extension, the extension never rings despite hearing a ring tone on the caller’s end.

It looks like the issue could be centralized around dialparties.agi. Has anyone else experienced this issue? Are there any tips to troubleshoot it?

I am on the latest version of FreePBX with Asterisk 1.6.0.

Here is the dump from the call. I notice the -1 error code exit from dialparties.agi towards the end. On a functional call (from within the PBX), the error code is 0 and asterisk seems to continue on to dial (despite a long delay).

Thanks for any help.
Brian

KodaK · October 8, 2008, 2:32pm

This is a copy and paste from a reply I made to a similar issue on the trixbox forums. It should be helpful for troubleshooting this issue:

I had an issue where dialparties.agi took forever to run because I enabled WINS resolution on my machine. This, in turn, caused php to take 12 seconds to initialize by itself, and dialparties.agi is written in php.

It looks like dialparties.agi may be taking a long time to run on your computer as well.

Some tips to help you troubleshoot:

Run this command:

time /bin/echo -e \n\n\n\n\n | /var/lib/asterisk/agi-bin/dialparties.agi

My times are:

real 0m0.081s
user 0m0.058s
sys 0m0.021s

If yours are significantly longer, then we know that dialparties.agi is the culprit. Now you just have to figure out what’s taking so long in dialparties.agi.

Run the command:

strace -r /bin/echo -e \n\n\n\n\n | /var/lib/asterisk/agi-bin/dialparties.agi

And it will tell you how long it takes to perform each step. Here’s the output from my system for that command:

[root@asterisk asterisk]# strace -r /bin/echo -e \n\n\n\n\n | /var/lib/asterisk/agi-bin/dialparties.agi
0.000000 execve("/bin/echo", ["/bin/echo", “-e”, “\n\n\n\n\n”], [/* 21 vars */]) = 0
0.000700 uname({sys=“Linux”, node=“asterisk.frontierhomemortgage.com”, …}) = 0
0.000476 brk(0) = 0x9163000
0.000177 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
0.000233 open("/etc/ld.so.cache", O_RDONLY) = 3
0.000215 fstat64(3, {st_mode=S_IFREG|0644, st_size=44293, …}) = 0
0.000238 old_mmap(NULL, 44293, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fe0000
0.000203 close(3) = 0
0.000171 open("/lib/tls/libc.so.6", O_RDONLY) = 3
0.000203 read(3, “\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\320\356”…, 512) = 512
0.000255 fstat64(3, {st_mode=S_IFREG|0755, st_size=1525004, …}) = 0
0.000229 old_mmap(0xbfa000, 1223900, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xbfa000
0.000254 old_mmap(0xd1f000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x124000) = 0xd1f000
0.000303 old_mmap(0xd23000, 7388, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xd23000
0.000307 close(3) = 0
0.000168 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fdf000
0.000278 mprotect(0xd1f000, 8192, PROT_READ) = 0
0.000187 mprotect(0xbf1000, 4096, PROT_READ) = 0
0.000157 set_thread_area({entry_number:-1 -> 6, base_addr:0xb7fdfaa0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
0.000285 munmap(0xb7fe0000, 44293) = 0
0.000296 brk(0) = 0x9163000
0.000146 brk(0x9184000) = 0x9184000
0.000214 open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
0.000249 fstat64(3, {st_mode=S_IFREG|0644, st_size=48520672, …}) = 0
0.000227 mmap2(NULL, 2097152, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7ddf000
0.000224 close(3) = 0
0.000248 fstat64(1, {st_mode=S_IFIFO|0600, st_size=0, …}) = 0
0.000254 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7dde000
0.000246 write(1, “\n\n\n\n\n\n”, 6) = 6
0.000157 close(1) = 0
0.000149 munmap(0xb7dde000, 4096) = 0
0.000197 exit_group(0) = ?
Process 23801 detached
VERBOSE “Starting New Dialparties.agi” 1
GET VARIABLE priority
VERBOSE “priority is 1” 1
VERBOSE “Caller ID name is ‘’ number is ‘’” 1
SET VARIABLE __KEEPCID "TRUE"
GET VARIABLE ARG1
GET VARIABLE ARG2
GET VARIABLE RingGroupMethod
GET VARIABLE PR_DIALSTATUS
GET VARIABLE NODEST
GET VARIABLE USE_CONFIRMATION
GET VARIABLE RINGGROUP_INDEX
VERBOSE “Methodology of ring is ‘none’” 1
VERBOSE “USE_CONFIRMATION: ‘FALSE’” 4
VERBOSE “RINGGROUP_INDEX: ‘’” 4
GET VARIABLE ARG3
NOOP
Content-type: text/html
X-Powered-By: PHP/4.3.11

I would suspect that the issue may lie with php, as it did with my system. If that’s the case, you can even try to find the delay in php by doing the following:

create a file called test.php and put the following in it:

<? print"Do you have stairs in your house?"; ?>

then run:

strace php ./test.php > /tmp/log 2>&1

then you can go through /tmp/log and see if you can find the delay.

It will be tedious. Just a friendly warning.

bmcglynn · October 9, 2008, 4:04pm

Thanks for the advise on debugging this. From running a timing test, it looks like there is a login issue that might explain the issue.

Any advise on how to debug this, or where to look would be immensely appreciated.

Thanks.


root@pbx:~ $ time /bin/echo -e \\n\\n\\n\\n\\n | /var/lib/asterisk/agi-bin/dialparties.agi
VERBOSE "PHPAGI internal configuration:" 1
VERBOSE "Array" 1
VERBOSE "(" 1
VERBOSE "    [phpagi] => Array" 1
VERBOSE "        (" 1
VERBOSE "            [debug] => 1" 1
VERBOSE "            [error_handler] => 1" 1
VERBOSE "            [admin] => [email protected]" 1
VERBOSE "            [hostname] => asterisk.local.net" 1
VERBOSE "            [tempdir] => /tmp" 1
VERBOSE "        )" 1
VERBOSE "" 1
VERBOSE "    [asmanager] => Array" 1
VERBOSE "        (" 1
VERBOSE "            [server] => localhost" 1
VERBOSE "            [port] => 5038" 1
VERBOSE "            [username] => asteriskuser" 1
VERBOSE "            [secret] => PASSWORD" 1
VERBOSE "        )" 1
VERBOSE "" 1
VERBOSE "    [fastagi] => Array" 1
VERBOSE "        (" 1
VERBOSE "            [setuid] => " 1
VERBOSE "            [basedir] => /var/lib/asterisk/agi-bin/" 1
VERBOSE "        )" 1
VERBOSE "" 1
VERBOSE "    [festival] => Array" 1
VERBOSE "        (" 1
VERBOSE "            [text2wave] => /usr/bin/text2wave" 1
VERBOSE "        )" 1
VERBOSE "" 1
VERBOSE "    [cepstral] => Array" 1
VERBOSE "        (" 1
VERBOSE "            [swift] => /opt/swift/bin/swift" 1
VERBOSE "            [voice] => David" 1
VERBOSE "        )" 1
VERBOSE "" 1
VERBOSE ")" 1
VERBOSE "" 1
VERBOSE "Starting New Dialparties.agi" 1
GET VARIABLE AMPMGRUSER
GET VARIABLE AMPMGRPASS
GET VARIABLE CWINUSEBUSY
GET VARIABLE ASTVERSION
GET VARIABLE ASTCHANDAHDI
GET VARIABLE CWIGNORE
GET VARIABLE CFIGNORE
Thu, 09 Oct 2008 11:57:11 -0400 - Failed to login.

bmcglynn · October 9, 2008, 5:04pm

In looking at the asterisk log during an inbound call, I can see the following error:


[Oct  9 12:48:52] VERBOSE[4317] logger.c:  dialparties.agi: Starting New Dialparties.agi
[Oct  9 12:48:52] NOTICE[4320] manager.c: 127.0.0.1 failed to authenticate as 'admin'
[Oct  9 12:48:53] VERBOSE[4320] logger.c:   == Connect attempt from '127.0.0.1' unable to authenticate

Does dialparties.agi look at a different location to get its credentials than other scripts? The rest of the PBX seems to function fine, so I wonder if there is something specific with the 2.5 release of FreePBX that conflicts with my system.

I did manually make some changes to /etc/asterisk/phpagi.conf to manually match the username to “admin” and the password to match the one it /etc/asterisk/manager.conf.

Any suggestions?

bmcglynn · October 9, 2008, 9:26pm

After a little digging, I found the credentials issue inside of dialparties.agi:


$AGI = new AGI();
debug("Starting New Dialparties.agi", 1);
// Get required channels variables that used to come from amportal.conf

$ampmgruser  = get_var( $AGI, “AMPMGRUSER” );

$ampmgrpass  = get_var( $AGI, “AMPMGRPASS” );

It apepars that these values come back as null (despite being configured in amportal.conf. The get_var function pulls the variables in from get_variable in the phpagi.agi file. There it looks like the value come back null.

Has anyone seen this before?

fskrotzki · October 10, 2008, 1:23pm

Please post this in the bug tracker. I’m going to guess that you changed the passwords from the defaults. And there might be a bug related to it working on * 1.6. FreePBX 2.5 is still currently listing support for * 1.6 as best effort due to it being in alpha/beta until just two weeks ago (they changed things from release to release which makes it very hard to guarantee support and compatibility.

Were you using * 1.6 with FreePBX 2.4? or did you upgrade to FreePBX 2.5 AND asterisk at the same time?

Also is your version of asterisk the final “released” version of 1.6 or one of the pre-releases…

danswartz · October 29, 2008, 1:26am

Can take as long as 12 seconds before it starts ringing (when I call from outside.) I am running asterisk 1.6.0.1. Will dig more…

Update: I set the user&pass manually in the script and now the test works, but same delay. I will look at the strace trick.

danswartz · October 29, 2008, 1:40am

I consistently see 7 second delay, and it’s from this in dialparties.agi:

$astman->disconnect();

I commented it out and the phone rings instantly. I will try to trace down what is going on and why…

danswartz · October 29, 2008, 8:00pm

This was due to a php configuration issue (php5 I think, which I had upgraded to from php4 quite some time ago). The problem is that my default timezone (TZ) was not set, so in strict mode, php kept puking warning messages to the syslog. I added the following to the [Date] section in /etc/php.ini and the 7-second delay vanished:

date.timezone = EST5EDT

twouters · September 10, 2009, 7:38am

danswartz, have you been able to find the source of this issue?
We are currently experiencing the same issue as described in this thread, except for your delay.

As a workaround we’ve also hardcoded the $username and $secret in phpagi-asmanager.php in the connect method. (At least I think it’s the same hack as you did)
The reason why we put it there is because those values were empty, even after the is_null() checks.

After some digging I’ve found out that there is either a bug in this section, where the check shouldn’t be is_null() but is_empty(), or a bug in dialparties.agi in the get_var() function, where the returned value shouldn’t be “’’” but “null”.

Although this seems a bug to me, I find it hard to believe that this bug is the cause of the issue. Have you ever figured that out or have you stopped digging after this little hack?

Kind regards