ASTERISK-27307: AMI Action 'Command' only returns the last line

[Home]

Summary: ASTERISK-27307: AMI Action 'Command' only returns the last line

Reporter: Ramon Peek-Fares (ramonpeek) Labels:

Date Opened: 2017-10-03 21:34:47 Date Closed: 2017-10-04 00:39:31

Priority: Minor Regression? Yes

Status: Closed/Complete Components: Core/ManagerInterface

Versions: 14.0.0 15.0.0-rc1 Frequency of
Occurrence Constant

Related
Issues:

Environment: CentOS 6.8 Attachments: ( 0) AMI-command-action-patch_v14.diff

Description: The AMI Action 'Command' only returns the last line from the output of a CLI command.
This is the case since the launch of Asterisk 14, which is described on the Asterisk Wiki as;

"The Command action now sends the output from the CLI command as a series of Output headers for each line instead of as a block of text with the --END COMMAND-- delimiter to match the output from other actions."
https://wiki.asterisk.org/wiki/display/AST/Upgrading+to+Asterisk+14

As a result we are no longer getting a useful response if the CLI command executed contains multiple lines, like 'core show channels' or 'sip show channels'
In these cases only the last line of the CLI Command is then reported on the "Output header"

The WiKi mentions; "a series of Output headers for each line"
But clearly that doesn't happen, we only get a single "output header".

I've written a simple patch that reverts this change.
Even though this works for me at the moment, reverting the change is a step backwards and likely not the correct way to continue.
I'd like to write a correct solution to the problem, but this requires me to know more about the reasons behind the original change.
However, I could not find the actual change anywhere in the ChangeLog or here on Jira.
Some assistance is appreciated.

Comments: By: Asterisk Team (asteriskteam) 2017-10-03 21:34:48.768-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: Ramon Peek-Fares (ramonpeek) 2017-10-03 21:37:12.420-0500

This is NOT A SOLUTION, but a patch to revert the change.
By: Ramon Peek-Fares (ramonpeek) 2017-10-03 21:44:36.552-0500

Here is an example..

On Asterisk 13, sending the command:
{quote}{code}Action : Command
command : sip show channels{code}{quote}

Would result in:
{quote}{code}UnformattedResponse : True
line3 : --END COMMAND--
line2 : 1 active SIP dialog
line1 : 192.168.161.100 (None) 57aa6af119aeed9 (nothing) No Rx: OPTIONS <guest>
line0 : Peer User/ANR Call ID Format Hold Last Message Expiry Peer
ActionID : 3
Privilege : Command
Response : Follows{code}{quote}

But on Asterisk 14, sending the same command results in;
{quote}{code}Output : 1 active SIP dialog
Message : Command output follows
Response : Success
ActionID : 3{code}{quote}

By: Joshua C. Colp (jcolp) 2017-10-03 21:49:04.115-0500

How are you using AMI? Did you use something like telnet to directly run the command and see the result? Are you using a library?
By: Ramon Peek-Fares (ramonpeek) 2017-10-03 22:02:25.859-0500

We are using our own application that creates an open-socket connection to the AMI (like a Telnet session)
Each message that is send by the AMI is captured by our application in a debug log, just as long as it contains a proper EOM marker.
(Our EOM identifier is set the ASCII code 04)
By: Ramon Peek-Fares (ramonpeek) 2017-10-03 22:12:52.903-0500

HOLD ON!
I just tested using telnet and I am able to see multiple output headers.
The question now is; are these lines correctly terminated so that our software recognises them as separate lines.
Will test some more on my side...
By: Joshua C. Colp (jcolp) 2017-10-03 22:15:15.430-0500

I just did this against 15.0.0 over telnet:

{noformat}
Action: Command
Command: pjsip show endpoints

Response: Success
Message: Command output follows
Output:
Output: Endpoint: <Endpoint/CID.....................................> <State.....> <Channels.>
Output: I/OAuth: <AuthId/UserName...........................................................>
Output: Aor: <Aor............................................> <MaxContact>
Output: Contact: <Aor/ContactUri..........................> <Hash....> <Status> <RTT(ms)..>
Output: Transport: <TransportId........> <Type> <cos> <tos> <BindAddress..................>
Output: Identify: <Identify/Endpoint.........................................................>
Output: Match: <criteria.........................>
Output: Channel: <ChannelId......................................> <State.....> <Time.....>
Output: Exten: <DialedExten...........> CLCID: <ConnectedLineCID.......>
Output: ==========================================================================================
Output:
Output: Endpoint: anonymous Unavailable 0 of 1
Output:
Output: Endpoint: doorbell Unavailable 0 of 1
Output: Aor: doorbell 10
Output:
Output: Endpoint: doorbell2 Unavailable 0 of 1
Output: Aor: doorbell2 10
Output:
Output: Endpoint: doorbell3 Unavailable 0 of 1
Output: Aor: doorbell3 10
Output:
Output: Endpoint: josh Unavailable 0 of 1
Output: Aor: josh 10
Output:
Output: Endpoint: webrtc Unavailable 0 of 1
Output:
Output:
Output: Objects found: 6
Output:
{noformat}

And it worked as expected. I'd suggest eliminating your application for the moment and doing the same. This will narrow down the scope to either Asterisk or how the application is handling things.
By: Joshua C. Colp (jcolp) 2017-10-03 22:16:22.503-0500

Understood. I'll leave it in feedback.
By: Ramon Peek-Fares (ramonpeek) 2017-10-03 22:30:25.868-0500

Found the cause to be in our own application.
Sorry, for the inconvenience.
But before we close the issue, one last question;

Our code first translates the AMI messages to a Python dictionary before dumping it into our debugger.
In this translate process, it uses everything before the ":" marker as the key name, and all behind as the value.
Because the key name is "Output", and is always the same, it get's overwritten thus resulting in only the last value to be shown.
However, this translation code already contained some special code (which I was unaware of) that handles "Unformatted Responses".
The previous unformatted responses where then converted to "line0:", "line1:", and so on. (which explains why you saw these in my first comment.)
I can adjust our code to do the same, for these new messages resolving the issue on our side.

But is it correct in assuming that ALL AMI responses containing lines starting with: "Output :" can be compared to the output of the old "Unformatted Responses"?
And are these "Output" headers always send as the last headers of the messages?

By: Ramon Peek-Fares (ramonpeek) 2017-10-03 23:25:07.164-0500

Well I've managed to adjust my code and now all data is being read normally again.
Our code requires each line to be stored in a unique key within a Python dictionary.
We used to translate these so called "Unformatted Responses", to a multi-line response when the message containing an entry "Response: Follows".
And for each "Unformatted Response" line we simply added the key "line0", "line1", "line2", and so on...
We now do the same for messages containing an entry "Message: Command output follows" and in which the "Response: Success".

I think this solution will tackle all messages containing this new format correctly, am I correct?

By: Joshua C. Colp (jcolp) 2017-10-04 00:39:26.651-0500

The change in question, https://gerrit.asterisk.org/#/c/139/, only modified the output for the Action: Command. It didn't touch any other. The change you mentioned on your side should be fine.