Adhearsion::Voip::Asterisk::AMI hangs
Reported by ronin-9952 (at lighthouseapp) | November 8th, 2007 @ 08:57 PM
When making calls to command() the system hangs completely.
attaching tar file with these files:
procfs-info README run.out strace.out testit.rb
short jist is that in parser.rb around line 178 to 183,
It would seem that wait() is releasing the mutex and the other thread
is never releasing the mutex back.
Also, it appears to me that we should not get to line 183 at the hang point because we have already logged (see run.out) the last lines of the command action response, so we should have returned at line179.
If either bug could be fixed, we'd have a usuable system, but both probably need fixed.
The asterisk full log with verbose and debug at 5 shows no errors at all
Comments and changes to this ticket
-
ronin-9952 (at lighthouseapp) November 8th, 2007 @ 09:13 PM
- no changes were found...
-
ronin-9952 (at lighthouseapp) February 21st, 2008 @ 05:07 PM
uploading a replacement attachemnt as the first one had run.out truncated.
-
ronin-9952 (at lighthouseapp) November 9th, 2007 @ 10:48 AM
many commands do not return Event: headers. All the commands I want to use currently end with
"--END COMMAND--\r\n\r\n"
some examples:
set verbose 5
sip show headers
show channels
core show channels
zap show status
zap show channels
show dialplan
say mode
so far every command I have tried that is not queues, queuestatus, or dbput/get ends with the above "end command " string
-
ronin-9952 (at lighthouseapp) November 9th, 2007 @ 12:56 PM
I tested against the flexmock server and against a real server. It appears that out of order headers from a real server may be the culprit:
What the flexmock server gives us:
Got 157 bytes, "Response: Follows\r\nActionID: 1194630034.25506\r\nPrivilege: Command\r\nChannel (Context Extension Pri ) State Appl. Data\n0 active channel(s)\r\n--END COMMAND--\r\n\r\n"
What a real asterisk server gives us:
Got 39 bytes, "Response: Follows\r\nPrivilege: Command\r\n"
Got 161 bytes, "ActionID: 1194630193.61866\r\nChannel Location State Application(Data) \n0 active channels\n0 active calls\n--END COMMAND--\r\n\r\n"
-
Jay Phillips November 9th, 2007 @ 06:07 PM
- State changed from “new” to “open”
-
ronin-9952 (at lighthouseapp) November 10th, 2007 @ 12:09 PM
A patch to flip the order of the headers.
wwalker@elephant:~/sandboxes/ahn-0.8.0-trunk-2$ svn diff spec/voip/asterisk/mock_ami_server.rb
Index: spec/voip/asterisk/mock_ami_server.rb
===================================================================
--- spec/voip/asterisk/mock_ami_server.rb (revision 586)
+++ spec/voip/asterisk/mock_ami_server.rb (working copy)
@@ -137,6 +142,7 @@
def response(action_id, args = {})
resp = []
resp << "Response: #{args.delete('Response')}" if args['Response']
- resp << "Privilege: Command" if args['Privilege']
resp << "Event: #{args.delete('Event')}" if args['Event']
resp << "ActionID: #{action_id}"
resp << "Message: #{args.delete('Message')}" if args['Message']
-
jhosteny November 16th, 2007 @ 10:55 AM
- Assigned user changed from “Jay Phillips” to “jhosteny”
Wayne, I'll take a look at this. Can you let me know exactly which version of Asterisk you are using, and what platform you ran the test on?
-
ronin-9952 (at lighthouseapp) November 16th, 2007 @ 12:07 PM
Asterisk 1.4.11
Linux (CentOS 5)
I have noticed that the system may send the response as 1 2 or 3 packets rather than just one. And that the order of the headers is different from Asterisk than from the FlexMock
I;m on freenode as wwalker most of the time.
lwwalkerbybent on AOL Instant Messenger too.
-
jhosteny November 16th, 2007 @ 01:00 PM
On Nov 16, 2007, at 12:07 PM, Lighthouse wrote:
// Add your reply here
I will check the flexmock. I suspect that that should not be the
problem, since it uses the first key to determine the packet type,
then parses the rest of the packet as key/value pairs. But I will make
sure it returns the data in the same order.
-
jhosteny November 16th, 2007 @ 01:04 PM
The rest of my reply got truncated. I also said:
However, receiving more than one packet definitely would be a problem. Do you have an example of what the output looks like? I'm in the process of rebuilding asterisk now - did you see this with the commands in your original ticket?
-
ronin-9952 (at lighthouseapp) November 16th, 2007 @ 01:08 PM
ruby -p -i -e " gsub(/localhost/,'dlsacs01')" spec/voip/asterisk/test_ami.rb
ruby -p -i -e " gsub(/flexmock/,'#flexmock')" spec/voip/asterisk/test_ami.rb
should allow it to run against a local asterisk server named dlsacs01 with a username password allowed by manager of admin/password
-
ronin-9952 (at lighthouseapp) November 16th, 2007 @ 01:23 PM
November 9th, 2007 @ 12:56 PM comment above shows that the data arrives in two separate packets. I've also once seen it arrive in 3 packets in my local testing.
It always ends a packet on "\r\n", but sometimes breaks after the second line, and someetimes after the second and fourth lines.
-
jhosteny November 16th, 2007 @ 01:25 PM
When making calls to command() the system hangs completely.
attaching tar file with these files:
procfs-info README run.out strace.out testit.rb
short jist is that in parser.rb around line 178 to 183,
It would seem that wait() is releasing the mutex and the other thread
is never releasing the mutex back.
Also, it appears to me that we should not get to line 183 at the hang point because we have already logged (see run.out) the last lines of the command action response, so we should have returned at line179.
If either bug could be fixed, we'd have a usuable system, but both probably need fixed.
The asterisk full log with verbose and debug at 5 shows no errors at all
-
jhosteny November 16th, 2007 @ 01:41 PM
I see what you mean now - this is actually just the read_nonblock call returning data in several chunks. The ragel code should handle this properly, scanning data as it arrives and running the state machine, and the result should be kicked up to the higher level as one packet.
I am able to reproduce the hang on the last command now though. I am investigating.
-
jhosteny November 16th, 2007 @ 03:34 PM
- State changed from “open” to “resolved”
Closed by changes #601 and #602. According to the docs, the "Command" action returns some key/val pairs, then a bunch of lines terminated by line feeds, one more line terminated by a crlf, then the "--END FOLLOWS--\r\n\r\n" terminator.
In reality, the last line of the "raw" output is terminated by a line feed only, not a crlf.
Fixed the test accordingly. Should check this against older versions of asterisk.
-
Jay Phillips August 29th, 2008 @ 02:02 AM
- Assigned user changed from “jhosteny” to “Jay Phillips”
- Tag set to “ami”
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.
Create new ticket
Create your profile
Help contribute to this project by taking a few moments to create your personal profile. Create your profile ยป
jhosteny