#103 ✓resolved
lpaszke

AGI request messages incorrectly ended

Reported by lpaszke | July 16th, 2010 @ 05:13 AM | in 0.8.5

Every agi request messages container generated by adhearsion is incorrectly ended causing error logs on asterisk (see below). This logs are generated because asterisk is waiting for "\n" at the end of each request. Currently adhesion do not follows this protocol, causing this logs to happen.

Asterisk 1.4.26 agi debug:

VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << temp buffer HANGUP - errno Resource temporarily unavailable VERBOSE[14792] logger.c: AGI Rx << HANGUP VERBOSE[14792] logger.c: AGI Tx >> 200 result=1

Comments and changes to this ticket

  • Ben Klang

    Ben Klang July 28th, 2010 @ 10:33 PM

    Hm, I have not seen this behavior. Can you share some additional information about your system? Which version of Adhearsion? Which version of Asterisk? On what OS is each piece running? Perhaps you could paste Adhearsion's debug log output as well. Anything else you can think of to help reproduce this problem would be helpful.

  • lpaszke

    lpaszke July 29th, 2010 @ 05:16 AM

    I see this error in Asterisk 1.4.26. To see this error you must turn on agi debug in asterisk (console command: agi debug). According to agi examples in "Asterisk the future of telephony" (http://downloads.oreilly.com/books/9780596510480.pdf) Chapter 9 (The Asterisk Gateway Interface (AGI)) subsections: Writing AGI Scripts in Perl, PHP, ect. there is "\n" after each agi request.

  • lpaszke

    lpaszke July 29th, 2010 @ 05:18 AM

    adhearsion 0.8.2

  • Ben Klang

    Ben Klang July 29th, 2010 @ 11:23 AM

    That is a pretty old version of Adhearsion. Please try updating the gem to the latest release, 0.8.4, and let me know if the issue persists.

  • lpaszke

    lpaszke July 30th, 2010 @ 05:22 AM

    Yes, the problem is present in 0.8.4.

  • Ben Klang

    Ben Klang July 30th, 2010 @ 10:43 AM

    Wait, I think I understand what you're reporting now. These messages appear in Asterisk's debug log when AGI debugging is enabled. Does the Adhearsion application otherwise work properly? If I enable AGI debug on my systems I see a similar flood of message. But note the final two messages:

    VERBOSE[14792] logger.c: AGI Rx << HANGUP
    VERBOSE[14792] logger.c: AGI Tx >> 200 result=1

    This indicates that the messages was received and processed by Asterisk. The log messages you are reporting are actually Asterisk's behavior: it loops over the socket, reading data until either the buffer fills up or it sees a newline. Each time it loops it prints out the contents of the temporary buffer. I've found this behavior so annoying that I actually modified res/res_agi.c to comment out that ast_verbose() line.

    But the bottom line is that, even though Asterisk is noisy, the AGI is (or should be) working fine. Adhearsion is in fact sending a newline, which is evidenced by the fact that the command is ultimately processed. Are you seeing any other errors related to AGI that make you think something is still broken?

  • lpaszke

    lpaszke July 30th, 2010 @ 11:21 AM

    Yes, Adhearsion sends new line at the beginning of next command, but Asterisk expect new line after command, therefore this logs appear. This is official Asterisk AGI behavior/protocol from the manual. This Adhearsion behavior is causing agi debag on asterisk side more difficult because of tons of irrelevant lines. It is not a critical problem, but very annoying.

  • lpaszke

    lpaszke July 30th, 2010 @ 11:35 AM

    Well, I am not sure If adhearsion sends new line at the begining of next command, but I am sure that asterisk is waiting for new line for a number of iterations, and executes agi command if end line is still absent after this number of iterations.

  • Ben Klang

    Ben Klang July 30th, 2010 @ 11:47 AM

    • State changed from “new” to “open”
    • Assigned user set to “Ben Klang”
    • Milestone set to “0.8.5”
    • Milestone order changed from “2” to “0”

    Wow. I'm quite surprised to discover this, but I can confirm your report by looking at the exchange on-the-wire with Wireshark. I will work on a fix for this; thanks for the report.

  • lpaszke

    lpaszke July 30th, 2010 @ 12:00 PM

    Great, thanks. I know about a number of other issues in Adhearsion. I will try to report them.

  • Ben Klang

    Ben Klang July 30th, 2010 @ 12:08 PM

    • State changed from “open” to “fixcommitted”

    I have pushed a fix for this issue. We still pass all unit tests, but I'd appreciate your help in validating the fix.

    Commit log:
    Terminate AGI commands with a newline [#103 status:fixcommitted]

    Adhearsion was using IO#print to send commands to AGI, which did not include a record separator (such as \n). This patch fixes that and updates the unit tests. Thanks to lpaszke for discovering the issue, reporting it, and patiently explaining it to me.

    http://github.com/adhearsion/adhearsion/commit/c5e553b57199b01d88d8...

  • Ben Klang

    Ben Klang August 2nd, 2010 @ 04:52 PM

    • State changed from “fixcommitted” to “open”

    The fix I pushed is causing trouble for me on at least one system. The newlines are being sent after Asterisk has accepted a seemingly unterminated line. This causes the newline by itself to trigger 500 errors and then the parser gets out of sync and loses state. I suspect the issue is in socket buffering somewhere, but I don't have a fix yet.

  • Ben Klang

    Ben Klang August 2nd, 2010 @ 05:32 PM

    • State changed from “open” to “fixcommitted”

    Since puts seems to be buffering the commands, I've elected to just append a newline to each message. This works for me on the system that was exhibiting strange behavior with puts. More testing is, as always, appreciated.

    Updated commit: http://github.com/adhearsion/adhearsion/commit/3d3427e162ae373a25cc...

  • Ben Klang

    Ben Klang August 24th, 2010 @ 01:55 PM

    • State changed from “fixcommitted” to “resolved”

Please Sign in or create a free account to add a new ticket.

With your very own profile, you can contribute to projects, track your activity, watch tickets, receive and update tickets through your email and much more.

New-ticket Create new ticket

Create your profile

Help contribute to this project by taking a few moments to create your personal profile. Create your profile ยป

Shared Ticket Bins

People watching this ticket

Tags

Referenced by

Pages