AGI is broken

[no]

It would appear that Asterisk is generating a warning message on one end of the AGI control pipe and treating this as a command on input.

To reproduce, put this in /etc/asterisk/extensions.ael:

  0 => {
    Answer;
    Wait(1);
    AGI(/bin/true);
    Wait(1);
    Hangup;
  }

asterisk-test*CLI> agi debug
AGI Debugging Enabled
asterisk-test*CLI> reload

Now dial 0:

    -- Executing Answer("SIP/x200-6445", "") in new stack
    -- Executing Wait("SIP/x200-6445", "1") in new stack
    -- Executing AGI("SIP/x200-6445", "/bin/true") in new stack
    -- Launched AGI Script /bin/true
AGI Tx >> agi_request: /bin/true
AGI Tx >> agi_channel: SIP/x200-6445
AGI Tx >> agi_language: en
AGI Tx >> agi_type: SIP
AGI Tx >> agi_uniqueid: 1144249499.100
AGI Tx >> agi_callerid: 200
AGI Tx >> agi_calleridname: Grandstream
AGI Tx >> agi_callingpres: 0
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: 0
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: inbound_sip
AGI Tx >> agi_extension: 0
AGI Tx >> agi_priority: 3
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode:
AGI Tx >>
AGI Rx << Apr 5 16:05:00 WARNING[9533]: asterisk.c:788 ast_set_priority: Unable to set normal priority
AGI Tx >> 510 Invalid or unknown command
    -- AGI Script /bin/true completed, returning 0
    -- Executing Wait("SIP/x200-6445", "1") in new stack
    -- Executing Hangup("SIP/x200-6445", "") in new stack
  == Spawn extension (inbound_sip, 0, 5) exited non-zero on 'SIP/x200-6445'

The text "asterisk.c:788 ast_set_priority: Unable to set normal priority" doesn't come from /bin/true!

I'm using the current version in Dapper:

asterisk-test*CLI> show version
Asterisk 1.2.1 built by buildd @ rothera on a i686 running Linux on 2006-01-03 10:13:21 UTC

# dpkg -l asterisk
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Installed/Config-files/Unpacked/Failed-config/Half-installed
|/ Err?=(none)/Hold/Reinst-required/X=both-problems (Status,Err: uppercase=bad)
||/ Name Version Description
+++-=======================================-=======================================-==============================================================================================
ii asterisk 1.2.1.dfsg-3 open source Private Branch Exchange (PBX)

This spurious output is causing AGI scripts to malfunction. I think it's also masking another bug where responses from Asterisk are being buffered (but because there's the spurious output, the reader happens to have some data to read and doesn't deadlock.)

[lukaso (launchpad-dby)]

Causing serious problems on my installation.

http://bugs.digium.com/view.php?id=7335&nbn=9

Claims it is fixed in SVN 34462 but I have no idea which release that corresponds too. Have not tested the fix.

Here is my transaction. However, where it shows the values coming back in order, I am actually only able to retrieve in one off order.

 -- Launched AGI Script /var/lib/asterisk/agi-bin/agistardead.agi
AGI Tx >> agi_request: agistardead.agi
AGI Tx >> agi_channel: SIP/2002-bd53
AGI Tx >> agi_language: en
AGI Tx >> agi_type: SIP
AGI Tx >> agi_uniqueid: asterisk-4771-1156401546.98
AGI Tx >> agi_callerid: unknown
AGI Tx >> agi_calleridname: lukas
AGI Tx >> agi_callingpres: 0
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: 18005551212
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: default
AGI Tx >> agi_extension: h
AGI Tx >> agi_priority: 1
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode:
AGI Tx >>
AGI Rx << Aug 24 07:39:28 WARNING[30315]: asterisk.c:807 ast_set_priority: Unable to set normal priority /* bogus command */
AGI Tx >> 510 Invalid or unknown command /* bogus result received after executing the next command */
AGI Rx << GET VARIABLE ANSWEREDTIME
AGI Tx >> 200 result=1 (10)
AGI Rx << GET VARIABLE DIALSTATUS
AGI Tx >> 200 result=1 (ANSWER)
AGI Rx << GET VARIABLE DIALEDTIME
AGI Tx >> 200 result=1 (22)
AGI Rx << GET VARIABLE BILLSTATUS
AGI Tx >> 200 result=0

[lukaso (launchpad-dby)]

Don't know if I should confirm, but am definitely seeing the bug.

[lukaso (launchpad-dby)]

The workaround is to make every call twice. The second call will retrieve the first result. However you can't get the first result without the second call. So really, your second call could be a dummy, but that won't work anymore when the bug is fixed.

[Soren Hansen (soren)]

Is this still an issue in current edgy?

[lukaso (launchpad-dby)]

Don't know. I don't have access to an Edgy machine. I think it is fixed in asterisk 1.2.9 but I haven't confirmed that either.

[Soren Hansen (soren)]

Have you upgraded to Edgy yet? Is it fixed?

[lukaso (launchpad-dby)]

I'm not upgrading to Edgy as I need an LTS system :)

[magilus (magilus)]

Fixed in Feisty (probably also in Edgy).

I created a Dapper task.

[rusivi2 (rusivi2-deactivatedaccount)]

Thank you for reporting this bug.

Dapper is in End of Life status. Please updated and repost detailed error report.

[Soren Hansen (soren)]

Dapper is not EOL on servers.

[Paul Belanger (pabelanger)]

Yes, however development for Asterisk 1.2 stop on 2007-08-07 and will be EOL 2010-11-21. I would suggest upgrading to 1.4 / 1.6.2 / 1.8

[JC Hulce (soaringsky)]

Thank you for reporting this bug to Ubuntu. The version of Ubuntu referenced in this issue has reached end of life, and the issue is fixed in newer versions of Ubuntu. Therefore, I am closing the Dapper task.
Please see this document for currently supported Ubuntu releases:
https://wiki.ubuntu.com/Releases