rspec spec/tropo2-conference_spec.rb../Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/niceogiri-0.0.4/lib/niceogiri/xml/node.rb:82: [BUG] Bus Error
ruby 1.8.7 (2010-08-16 patchlevel 302) [i686-darwin10.4.2]

Abort trap

Seems to be related to line 2389 (sipmethod.log): https://gist.github.com/9bccaad10224eeb2d8df

May be related to this ticket:

https://github.com/tropo/tropo2/issues/61

See Tropo2 issue https://github.com/tropo/tropo2/issues/46

As per issue #3 the surrounding is no longer necessary https://github.com/tropo/tropo2/issues/4

<answered/> and <ringing/>

https://github.com/tropo/tropo2/issues/49

This will be added in the next Tropo2 sprint.

It appears that an Info message does not add the xmlns as an accessor:

Info

#<Punchblock::Protocol::Ozone::Info:0x1023e8340 @type=:ring, @cmd_id=nil, @parent=nil, @call_id="7f374efc-a402-4e23-a1f5-e82022463d86", @xml=#<Punchblock::Protocol::Ozone::MessageProxy:0x811f3d54 name="info" attributes=[#<Nokogiri::XML::Attr:0x811f3458 name="xmlns" value="urn:xmpp:ozone:info:1">]>, @attributes={}>

End

#<Punchblock::Protocol::Ozone::End:0x1023d8738 @type=:reject, @cmd_id=nil, @parent=nil, @call_id="89e3f26c-25ca-44f4-b97c-453799ea3a1d", @xml=#<Punchblock::Protocol::Ozone::MessageProxy:0x811ec02c name="end" attributes=[#<Nokogiri::XML::Attr:0x811ebc30 name="xmlns" value="urn:xmpp:ozone:end:1">]>>

Like the other messages do:

Say

#<Punchblock::Protocol::Ozone::Complete:0x102384638 @attributes={:reason=>"SUCCESS"}, @cmd_id="21460cc5-44bb-4a1a-9d6c-3fd401687d4b", @call_id="951f7bf6-d440-4364-841a-f1b13e9f77a7", @parent=nil, @xmlns="urn:xmpp:ozone:say:1", @xml=#<Punchblock::Protocol::Ozone::MessageProxy:0x811c2204 name="complete" attributes=[#<Nokogiri::XML::Attr:0x811c1f5c name="xmlns" value="urn:xmpp:ozone:complete:1">]>>

The presence callback is only called once pry returns. https://gist.github.com/1214f0cf7277e02f43c6

Tailing the transport log when issuing hangup then exit shows this perfectly.

On an Ask, we get this back if the farside hangs up before the Ask is done:

<iq type="set" from="[email protected]/068ff9ea-54e3-4803-9a72-992fc754cb7e" to="[email protected]/voxeo" id="f43b6608-ef72-4f0c-b260-b05750c5d8d8">
  <complete xmlns="urn:xmpp:ozone:ask:1" confidence="0.0">
    <error>Could not complete Ask at this time.</error>
  </complete>
</iq>

We should surface that as an Ask Error class.

https://gist.github.com/a123ee77b128cd971127

 Failure/Error: @tropo2.hangup.should eql true
 NoMethodError:
   undefined method `call_id' for nil:NilClass
 # /Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/transport/xmpp.rb:94:in `write'
 # /Users/jsgoecke/Dropbox/Development/rspec-tropo2/lib/rspec-tropo2/tropo2-driver.rb:31:in `hangup'
 # ./spec/tropo2-dial_spec.rb:14

Would you mind if we added this as a development dependency?

https://github.com/nicksieger/ci_reporter

^Capollo:tropo2_functional_tester jsgoecke$ rspec spec/tropo2-functional_spec.rb-format doc -l 267
Run filtered including {:line_number=>267}

Tropo2AutomatedFunctionalTesting
"Starting Tropo2Driver to manage events over XMPP."
"Starting Tropo1Driver to host scripts via DRb and launch calls via HTTP."
"Connected to the Tropo2 XMPP Server"
"Starting tests..."
Transfer verb
8f51510198429c136813cd13313e905f
Exception in XMPP thread!



java.lang.IllegalArgumentException: Unsupported format: [email protected]


/Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/transport/xmpp.rb:65:in initialize' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:270:incall'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:270:in call_handler' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:261:incall_handler_for'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:261:in catch' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:261:incall_handler_for'
/Users/jsgoecke/.rvm/rubies/ruby-1.8.7-p302/lib/ruby/1.8/resolv.rb:497:in find' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:260:ineach'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:260:in find' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:260:incall_handler_for'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:253:in handle_stanza' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:252:ineach'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:252:in handle_stanza' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:178:inreceive_data'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:176:in catch' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:176:inreceive_data'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream.rb:198:in receive' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream/parser.rb:98:indeliver'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream/parser.rb:78:in end_element_namespace' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/nokogiri-1.4.4/lib/nokogiri/xml/sax/push_parser.rb:47:innative_write'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/nokogiri-1.4.4/lib/nokogiri/xml/sax/push_parser.rb:47:in <<' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream/parser.rb:24:in<<'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream.rb:147:in receive_data' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/eventmachine-0.12.10/lib/eventmachine.rb:256:inrun_machine'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/eventmachine-0.12.10/lib/eventmachine.rb:256:in run' /Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/transport/xmpp.rb:95:inrun'
/Users/jsgoecke/Dropbox/Development/rspec-tropo2/lib/rspec-tropo2/tropo2-driver.rb:98:in start_tropo2' /Users/jsgoecke/Dropbox/Development/rspec-tropo2/lib/rspec-tropo2/tropo2-driver.rb:96:ininitialize'
/Users/jsgoecke/Dropbox/Development/rspec-tropo2/lib/rspec-tropo2/tropo2-driver.rb:96:in new' /Users/jsgoecke/Dropbox/Development/rspec-tropo2/lib/rspec-tropo2/tropo2-driver.rb:96:instart_tropo2'
/Users/jsgoecke/Dropbox/Development/rspec-tropo2/lib/rspec-tropo2/tropo2-driver.rb:80:in initialize_tropo2' /Users/jsgoecke/Dropbox/Development/rspec-tropo2/lib/rspec-tropo2/tropo2-driver.rb:7:ininitialize'
/Users/jsgoecke/Dropbox/Development/tropo2_functional_tester/spec/tropo2-functional_spec.rb:10:in new' /Users/jsgoecke/Dropbox/Development/tropo2_functional_tester/spec/tropo2-functional_spec.rb:10 /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/hooks.rb:32:ininstance_eval'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/hooks.rb:32:in run_in' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/hooks.rb:73:inrun_all!'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/hooks.rb:121:in run_hook!' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/example_group.rb:207:ineval_before_alls'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/example_group.rb:261:in run' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/command_line.rb:24:inrun'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/command_line.rb:24:in map' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/command_line.rb:24:inrun'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/reporter.rb:12:in report' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/command_line.rb:21:inrun'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/runner.rb:80:in run_in_process' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/runner.rb:69:inrun'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/runner.rb:11:in `autorun'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/bin/rspec:19

From the inner_text path below:

<iq type="error" id="blather000e" from="[email protected]" to="[email protected]/voxeo">
  <hangup xmlns="urn:xmpp:ozone:1"/>
  <error type="cancel">
    <item-not-found xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/>
    <text xmlns="urn:ietf:params:xml:ns:xmpp-stanzas" lang="en">Could not find call [id=f6d437f4-1e18-457b-99f8-b5d853f50347]</text>
  </error>
</iq>

Need to get rid of the dashes in these symbols:

{:"call-id"=>"6yemrc31qlda", :contact=>"sip:10.0.1.11:5060;transport=udp", :cseq=>"1 INVITE", :to=>"sip:[email protected]", :"content-type"=>"application/sdp", :"max-forwards"=>"70", :via=>"SIP/2.0/UDP 10.0.1.11:5060;branch=z9hG4bKum26pej6j7o6;rport=5060", :from=>"sip:[email protected];tag=1jclbk3c9v1hn", :"content-length"=>"428", :"x-vdirect"=>"true"}

write @call_event, @protocol::Redirect.new(destination)

Returns this:

"sip:[email protected]"

Rather than 'true' like the rest of the commands.

If I understand the scenario correctly, the Message::Say.new 'http://foobar.com', :url should return an object that I may then do something like:

say = @protocol::Message::Say.new 'http://foobar.com', :url
say.pause
say.resume

The issue is, the Say does not return an object before playback is over so that I may act upon it. Here is the wire and transport log:

https://gist.github.com/d4da52b914cb00d22c9f

Rather than simply returning an element to send

Right now, by two bugs making one right, it turns out passing SSML and GRXML as a string gets escaped by Nokogiri (when inner_text) and Ozone just happens to unescape, but should not. So, we need to either accept a valid Nokogiri::XML object or if it is a String convert into a valid Nokogiri::XML object and stuff it in the tag.

Right now the interface between the Ozone Protocol and the Transport is a Nokogiri XML object. This works, but may prove to be an expensive transition in the future since it requires parsing the Nokogiri Object <-> Punchblock::Message Object in and out. We don't want to focus on pre-optimization, so will keep it as is, but may want to consider using a simple String with XML in it in the future, since the Ozone XML schema is relatively simple.

The issue here is determining how to get Blather/Nokogiri not to escape the XML in a String when doing a write_stream.

So that it only has offers to be processed.

Punchblock::Protocol::Ozone::Message::End:0x1023d6208 @call_id=nil, @parent=nil, @cmd_id=nil, @xml=#<Punchblock::Protocol::Ozone::MessageProxy:0x811eaed4 name="end" attributes=[#<Nokogiri::XML::Attr:0x811e9688 name="xmlns" value="urn:xmpp:ozone:end:1">]

Right now, on an Ask for example, the call to super('ask') is not setting in of the attribute variables like there should be in here:

https://gist.github.com/f5436f2b756dc7bd04c3

While the Punchblock does preserve the 'xmlns' it did not preserve things like timeout an recognizer.

Right now the Transfer class does not accept headers, but should.

      call.transfer(:to      => @config['tropo1']['call_destination'],
                    :headers => { 'x-tropo2-drb-address' => @config['tropo2_server']['drb_server_address'] }).should eql true

  1) Tropo2AutomatedFunctionalTesting Transfer verb Should answer a call and then transfer it
     Failure/Error: call.transfer(:to      => @config['tropo1']['call_destination'],
     NoMethodError:
       undefined method `headers=' for #<Punchblock::Protocol::Ozone::Transfer:0x1024dc5f8>
     # /Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/protocol/ozone/transfer.rb:26:in `send'
     # /Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/protocol/ozone/transfer.rb:26:in `new'
     # /Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/protocol/ozone/transfer.rb:26:in `each_pair'
     # /Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/protocol/ozone/transfer.rb:26:in `new'
     # /Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/protocol/ozone/transfer.rb:25:in `tap'
     # /Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/protocol/ozone/transfer.rb:25:in `new'
     # /Users/jsgoecke/Dropbox/Development/rspec-tropo2/lib/rspec-tropo2/tropo2-call.rb:51:in `transfer'
     # ./spec/tropo2-transfer_spec.rb:24

While in reality this scenario should not occur, we should try to gracefully handle the XMPP errors like this one:

Exception in XMPP thread! Extra content at the end of the document

https://gist.github.com/3d742f776f4c0455646e

As per issue #3 the surrounding is no longer necessary https://github.com/tropo/tropo2/issues/4

Ideally, punchblock would give you a reference to the command object, something like complete_event.source, where source is for example the Conference object you sent to the server. So when you have a scenario like this:

https://gist.github.com/1918b90b7c59b6d0bbe7

It would be easy to match against the calling command.

https://github.com/tropo/tropo2/issues/47

This is scheduled to be implemented in Tropo2 during the next sprint.

Right now, there is no indication that the executable is attempting to connect or is connected. We should add some logging that lets us see what is happening and report when it may now accept calls and launch a Pry instance.

eg a Say#pause! completing should mark the Say as paused. Relies on this: https://github.com/tropo/punchblock/issues/48

Exception in XMPP thread! undefined method value' for nil:NilClass /Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/protocol/ozone.rb:433:inparse'
/Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/protocol/ozone.rb:431:in tap' /Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/protocol/ozone.rb:431:inparse'
/Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/protocol/ozone.rb:71:in parse' /Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/transport/xmpp.rb:45:ininitialize'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:270:in call' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:270:incall_handler'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:261:in call_handler_for' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:261:incatch'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:261:in call_handler_for' /Users/jsgoecke/.rvm/rubies/ruby-1.8.7-p302/lib/ruby/1.8/resolv.rb:497:infind'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:260:in each' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:260:infind'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:260:in call_handler_for' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:253:inhandle_stanza'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:252:in each' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:252:inhandle_stanza'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:178:in receive_data' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:176:incatch'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:176:in receive_data' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream.rb:198:inreceive'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream/parser.rb:98:in deliver' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream/parser.rb:78:inend_element_namespace'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/nokogiri-1.4.4/lib/nokogiri/xml/sax/push_parser.rb:47:in native_write' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/nokogiri-1.4.4/lib/nokogiri/xml/sax/push_parser.rb:47:in<<'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream/parser.rb:24:in <<' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream.rb:147:inreceive_data'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/eventmachine-0.12.10/lib/eventmachine.rb:256:in run_machine' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/eventmachine-0.12.10/lib/eventmachine.rb:256:inrun'
/Users/jsgoecke/Dropbox/Development/punchblock/lib/punchblock/transport/xmpp.rb:95:in run' /Users/jsgoecke/Dropbox/Development/rspec-tropo2/lib/rspec-tropo2/tropo2-driver.rb:86:instart_tropo2'
/Users/jsgoecke/Dropbox/Development/rspec-tropo2/lib/rspec-tropo2/tropo2-driver.rb:84:in initialize' /Users/jsgoecke/Dropbox/Development/rspec-tropo2/lib/rspec-tropo2/tropo2-driver.rb:84:innew'
/Users/jsgoecke/Dropbox/Development/rspec-tropo2/lib/rspec-tropo2/tropo2-driver.rb:84:in start_tropo2' /Users/jsgoecke/Dropbox/Development/rspec-tropo2/lib/rspec-tropo2/tropo2-driver.rb:68:ininitialize_tropo2'
/Users/jsgoecke/Dropbox/Development/rspec-tropo2/lib/rspec-tropo2/tropo2-driver.rb:7:in initialize' /Users/jsgoecke/Dropbox/Development/tropo2_functional_tester/spec/tropo2-functional_spec.rb:10:innew'
/Users/jsgoecke/Dropbox/Development/tropo2_functional_tester/spec/tropo2-functional_spec.rb:10
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/hooks.rb:32:in instance_eval' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/hooks.rb:32:inrun_in'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/hooks.rb:73:in run_all!' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/hooks.rb:121:inrun_hook!'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/example_group.rb:207:in eval_before_alls' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/example_group.rb:261:inrun'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/command_line.rb:24:in run' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/command_line.rb:24:inmap'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/command_line.rb:24:in run' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/reporter.rb:12:inreport'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/command_line.rb:21:in run' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/runner.rb:80:inrun_in_process'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/runner.rb:69:in run' /Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/rspec-core-2.6.0/lib/rspec/core/runner.rb:11:inautorun'
/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/bin/rspec:19

I notice when I run tests, somewhere there is a write to STDOUT of the value 849358c4e0bfae5b1b2cf69e92eb5fc2:

Tropo2AutomatedFunctionalTesting
"Starting Tropo2Driver to manage events over XMPP."
"Starting Tropo1Driver to host scripts via DRb and launch calls via HTTP."
"Connected to the Tropo2 XMPP Server"
"Starting tests..."
Call answer and hangup handling
c8488da58dae1da93ae6900dd9295053
Should receive a call arrives and then hangup
e3a8c277173c2cfc8b94ee8a5b895d24
Should accept, answer and hangup
Should answer a call and let the farside hangup (PENDING: This bug being fixed: https://evolution.voxeo.com/ticket/1423272)
Say verb
849358c4e0bfae5b1b2cf69e92eb5fc2
Should say something with TTS
Should say some audio, wait 2 seconds, pause, wait 2 seconds, resume, wait 2 seconds and then stop (PENDING: Punchblock object model)
Ask verb
Should ask something with ASR and get the utterance back (PENDING: https://github.com/tropo/punchblock/issues/8)
Transfer verb
Should answer a call and then transfer it (PENDING: Punchblock object model)

252b14a..8c71e9f feature/ozone_protocol_changes -> origin/feature/ozone_protocol_changes
Already up-to-date.
tropo-rox:punchblock jsgoecke$ rake spec
/Users/jsgoecke/.rvm/rubies/ruby-1.8.7-p334/bin/ruby -S bundle exec rspec --color spec/protocol/ozone_messages_spec.rb spec/transport/xmpp_spec.rb
Could not find rake-0.9.1 in any of the sources
rake aborted!
ruby -S bundle exec rspec --color spec/protocol/ozone_messages_spec.rb spec/transport/xmpp_spec.rb failed

Tasks: TOP => spec
(See full trace by running task with --trace)
tropo-rox:punchblock jsgoecke$

Full backtrace and logs here:

https://gist.github.com/e8382974cca5e5a3ff98

I know the thread has been moved and it is no longer necessary, but we do appear to be getting a deadlock intermittently:

deadlock 0x2b3c7bce5378: sleep:J(0x2b3c7cbb4b60) (main) - /home/jsgoecke/.rvm/gems/ruby-1.8.7-p334/gems/conference_tropo2-0.1.0/bin/conference:40
deadlock 0x2b3c7cbb4b60: sleep:- - /home/jsgoecke/.rvm/gems/ruby-1.8.7-p334/gems/conference_tropo2-0.1.0/lib/conference_tropo2/driver.rb:45
/home/jsgoecke/.rvm/gems/ruby-1.8.7-p334/gems/punchblock-0.1.0/lib/punchblock/protocol/ozone/connection.rb:79: Thread(0x2b3c7cd82ff0): deadlock (fatal)
from /home/jsgoecke/.rvm/gems/ruby-1.8.7-p334/gems/conference_tropo2-0.1.0/bin/conference:40:in each' from /home/jsgoecke/.rvm/gems/ruby-1.8.7-p334/gems/conference_tropo2-0.1.0/bin/conference:40 from /home/jsgoecke/.rvm/gems/ruby-1.8.7-p334/bin/conference:19:inload'
from /home/jsgoecke/.rvm/gems/ruby-1.8.7-p334/bin/conference:19

Based on this code:

    def start_tropo2
      @threads << Thread.new do
        begin
          @tropo2.run
        rescue => e
          puts "Exception in XMPP thread! #{e.message}"
          puts e.backtrace.join("\t\n")
        end
      end
    end

I will run with:

Thread.abort_on_exception = true

And see if I may get more detail.

Based on this:

https://github.com/tropo/punchblock/commit/8d945c0f53b3f51129081d4d59a78ec9681d628a

Add another test that will test passing multiple headers consistently on OSX and Linux.

"Punchblock::Protocol::Ozone::Message::Complete:0x1023b7740 @xmlns="urn:xmpp:ozone:ask:1", @call_id="d58e1142-ba63-44e9-b677-c1056d2779d0", @xml=#<Punchblock::Protocol::Ozone::MessageProxy:0x811dba9c name="complete" attributes=[#<Nokogiri::XML::Attr:0x811db8a8 name="xmlns" value="urn:xmpp:ozone:complete:1">]>, @cmd_id="24037d96-6089-4058-9aaf-f5f3bd5ae723", @parent=nil"

wire.log:

Logfile created on Wed May 25 15:36:30 -0700 2011 by logger.rb/22285

D, [2011-05-25T15:36:41.879416 #24630] DEBUG -- : NEW JID: [email protected]
D, [2011-05-25T15:36:41.970235 #24630] DEBUG -- : SENDING: (/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream/client.rb:20:in `start') <stream:stream to='10.0.1.11' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' xml:lang='en' >

D, [2011-05-25T15:36:41.977823 #24630] DEBUG -- :

D, [2011-05-25T15:36:41.977903 #24630] DEBUG -- : STREAM IN: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" xmlns:db="jabber:server:dialback" version="1.0" from="10.0.1.11" id="xmpps_1qzfc8gebrleg" xml:lang="en">
D, [2011-05-25T15:36:41.978230 #24630] DEBUG -- : RECEIVING (stream) <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns:db="jabber:server:dialback" version="1.0" from="10.0.1.11" id="xmpps_1qzfc8gebrleg" lang="en"/>

D, [2011-05-25T15:36:41.979736 #24630] DEBUG -- :

D, [2011-05-25T15:36:41.979795 #24630] DEBUG -- : STREAM IN: stream:featuresPLAIN/stream:features
D, [2011-05-25T15:36:41.980046 #24630] DEBUG -- : RECEIVING (features) <stream:features xmlns:stream="http://etherx.jabber.org/streams">

PLAIN

/stream:features
D, [2011-05-25T15:36:41.980478 #24630] DEBUG -- : SENDING: (/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream/features/sasl.rb:175:in `authenticate') dXNlcmFAMTAuMC4xLjExAHVzZXJhADE=

D, [2011-05-25T15:36:41.983811 #24630] DEBUG -- :

D, [2011-05-25T15:36:41.983906 #24630] DEBUG -- : STREAM IN:
D, [2011-05-25T15:36:41.984050 #24630] DEBUG -- : RECEIVING (success)
D, [2011-05-25T15:36:41.984238 #24630] DEBUG -- : SENDING: (/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream/client.rb:20:in `start') <stream:stream to='10.0.1.11' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' xml:lang='en' >

D, [2011-05-25T15:36:41.989551 #24630] DEBUG -- :

D, [2011-05-25T15:36:41.989655 #24630] DEBUG -- : STREAM IN: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" xmlns:db="jabber:server:dialback" version="1.0" from="10.0.1.11" id="xmpps_1qzfc8gebrleg" xml:lang="en">
D, [2011-05-25T15:36:41.989835 #24630] DEBUG -- : RECEIVING (stream) <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns:db="jabber:server:dialback" version="1.0" from="10.0.1.11" id="xmpps_1qzfc8gebrleg" lang="en"/>

D, [2011-05-25T15:36:41.990268 #24630] DEBUG -- :

D, [2011-05-25T15:36:41.990328 #24630] DEBUG -- : STREAM IN: stream:features/stream:features
D, [2011-05-25T15:36:41.990548 #24630] DEBUG -- : RECEIVING (features) <stream:features xmlns:stream="http://etherx.jabber.org/streams">


/stream:features
D, [2011-05-25T15:36:41.990906 #24630] DEBUG -- : SENDING: (/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream/features/resource.rb:38:in `bind')

D, [2011-05-25T15:36:41.994279 #24630] DEBUG -- :

D, [2011-05-25T15:36:41.994388 #24630] DEBUG -- : STREAM IN: [email protected]/voxeo
D, [2011-05-25T15:36:42.004198 #24630] DEBUG -- : RECEIVING (iq)

[email protected]/voxeo


D, [2011-05-25T15:36:42.004442 #24630] DEBUG -- : RESOURCE NODE

[email protected]/voxeo


D, [2011-05-25T15:36:42.004618 #24630] DEBUG -- : NEW JID: [email protected]/voxeo
D, [2011-05-25T15:36:42.005162 #24630] DEBUG -- : SENDING: (/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/stream/features/session.rb:39:in `session')

D, [2011-05-25T15:36:42.008208 #24630] DEBUG -- :

D, [2011-05-25T15:36:42.008297 #24630] DEBUG -- : STREAM IN:
D, [2011-05-25T15:36:42.008479 #24630] DEBUG -- : RECEIVING (iq)


D, [2011-05-25T15:36:42.008923 #24630] DEBUG -- : SENDING: (/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:140:in `write')

D, [2011-05-25T15:36:42.016021 #24630] DEBUG -- :

D, [2011-05-25T15:36:42.016092 #24630] DEBUG -- : STREAM IN:
D, [2011-05-25T15:36:42.016368 #24630] DEBUG -- : RECEIVING (iq)





D, [2011-05-25T15:36:42.017099 #24630] DEBUG -- : SENDING: (/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:140:in `write')

D, [2011-05-25T15:36:43.519536 #24630] DEBUG -- :

D, [2011-05-25T15:36:43.519649 #24630] DEBUG -- : STREAM IN:

D, [2011-05-25T15:36:43.729774 #24630] DEBUG -- :

D, [2011-05-25T15:36:43.729886 #24630] DEBUG -- : STREAM IN:
D, [2011-05-25T15:36:43.730069 #24630] DEBUG -- : RECEIVING (iq)

D, [2011-05-25T15:36:43.731509 #24630] DEBUG -- :

D, [2011-05-25T15:36:43.731593 #24630] DEBUG -- : STREAM IN:
D, [2011-05-25T15:36:43.731816 #24630] DEBUG -- : RECEIVING (iq)




D, [2011-05-25T15:36:43.732613 #24630] DEBUG -- : SENDING: (/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:140:in `write')

D, [2011-05-25T15:36:43.732834 #24630] DEBUG -- :

D, [2011-05-25T15:36:43.732893 #24630] DEBUG -- : STREAM IN:
D, [2011-05-25T15:36:43.733103 #24630] DEBUG -- : RECEIVING (iq)




D, [2011-05-25T15:36:43.733821 #24630] DEBUG -- : SENDING: (/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:140:in write') <iq type="result" id="6e72e773-9527-4f52-bad2-7f215d29bea6" from="[email protected]/voxeo" to="[email protected]"><info xmlns="urn:xmpp:ozone:1"><answer/></info></iq> D, [2011-05-25T15:36:43.734942 #24630] DEBUG -- : SENDING: (/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:140:inwrite')

One

yes, no

D, [2011-05-25T15:36:43.859748 #24630] DEBUG -- :

D, [2011-05-25T15:36:43.859866 #24630] DEBUG -- : STREAM IN:
D, [2011-05-25T15:36:43.860129 #24630] DEBUG -- : RECEIVING (iq)

D, [2011-05-25T15:36:43.881626 #24630] DEBUG -- :

D, [2011-05-25T15:36:43.881711 #24630] DEBUG -- : STREAM IN: Could not complete Ask at this time.
D, [2011-05-25T15:36:43.881955 #24630] DEBUG -- : RECEIVING (iq)

Could not complete Ask at this time.


D, [2011-05-25T15:36:43.882770 #24630] DEBUG -- : SENDING: (/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:140:in write') <iq type="result" id="8a152d11-9b1c-49c1-b4ef-86136a9fe7ba" from="[email protected]/voxeo" to="[email protected]/24037d96-6089-4058-9aaf-f5f3bd5ae723"><complete xmlns="urn:xmpp:ozone:ask:1" confidence="0.0"><error>Could not complete Ask at this time.</error></complete></iq> D, [2011-05-25T15:36:43.884019 #24630] DEBUG -- : SENDING: (/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:140:inwrite')

D, [2011-05-25T15:36:44.003152 #24630] DEBUG -- :

D, [2011-05-25T15:36:44.003263 #24630] DEBUG -- : STREAM IN:
D, [2011-05-25T15:36:44.003640 #24630] DEBUG -- : RECEIVING (iq)

D, [2011-05-25T15:36:44.005894 #24630] DEBUG -- :

D, [2011-05-25T15:36:44.005978 #24630] DEBUG -- : STREAM IN:
D, [2011-05-25T15:36:44.006218 #24630] DEBUG -- : RECEIVING (iq)




D, [2011-05-25T15:36:44.007021 #24630] DEBUG -- : SENDING: (/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.4.16/lib/blather/client/client.rb:140:in `write')

With this test:

    it "Should answer a call and then transfer it" do
      @tropo1.script_content = <<-SCRIPT_CONTENT
        call 'sip:' + '#{@config['tropo2_server']['sip_uri']}'
        wait #{@config['tropo1']['wait_to_hangup']}
      SCRIPT_CONTENT
      @tropo1.place_call @config['tropo1']['session_url']

      call = @tropo2.get_call
      call.call_event.should be_a_valid_call_event
      call.answer.should eql true

      # Set a script that handles the incoming Xfer from Tropo2
      @tropo1.script_content = <<-SCRIPT_CONTENT
        answer
        wait 1000
        hangup
      SCRIPT_CONTENT

      call.transfer(:to => @config['tropo1']['call_destination']).should eql true
      call.next_event.should be_a_valid_transfer_event
      call.next_event.should be_a_valid_hangup_event

      call.last_event?(@config['tropo2_queue']['last_stanza_timeout']).should eql true
    end

I get this result:

D, [2011-06-10T15:12:15.202314 #30789] DEBUG -- : SENDING: (/Users/jsgoecke/.rvm/gems/ruby-1.8.7-p302/gems/blather-0.5.2/lib/blather/client/client.rb:145:in `write') <iq type="set" to="[email protected]" id="blather000a" from="[email protected]/voxeo"><transfer xmlns="urn:xmpp:ozone:transfer:1"/></iq>
D, [2011-06-10T15:12:15.298380 #30789] DEBUG -- : 
------------------------------

D, [2011-06-10T15:12:15.298491 #30789] DEBUG -- : STREAM IN: <iq type="error" to="[email protected]/voxeo" id="blather000a" from="[email protected]"><transfer xmlns="urn:xmpp:ozone:transfer:1"/><error type="modify"><bad-request xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/><text xmlns="urn:ietf:params:xml:ns:xmpp-stanzas" xml:lang="en">Missing required attribute 'to'</text></error></iq>
D, [2011-06-10T15:12:15.298809 #30789] DEBUG -- : RECEIVING (iq) <iq type="error" to="[email protected]/voxeo" id="blather000a" from="[email protected]">
  <transfer xmlns="urn:xmpp:ozone:transfer:1"/>
  <error type="modify">
    <bad-request xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/>
    <text xmlns="urn:ietf:params:xml:ns:xmpp-stanzas" lang="en">Missing required attribute 'to'</text>
  </error>
</iq>

https://gist.github.com/6e4573a5a13081cbbc99

This event:

<iq type="set" from="[email protected]/9520de6e-a2c8-4a6b-a5c0-c8a33f31cf76" to="[email protected]/voxeo" id="e2444db4-60d9-4c7c-ac25-5c3b6600d5cc">
  <off-hold xmlns="urn:xmpp:ozone:conference:1"/>

Appears to throw a nil on the event_queue text.log on line 3 in the above gist. That gist also has the other relevant logs and spec.

When I do this:

ask({ :text => 'One', :choices => 'yes, no', :grammar => 'application/grammar+voxeo' })

I get this result:

<iq type="set" to="[email protected]" id="blather000a" from="[email protected]/voxeo"><ask xmlns="urn:xmpp:ozone:ask:1"><prompt/><choices content-type="application/grammar+voxeo"></choices></ask></iq>

<iq type="error" to="[email protected]/voxeo" id="blather000a" from="[email protected]">
  <ask xmlns="urn:xmpp:ozone:ask:1">
    <prompt/>
    <choices content-type="application/grammar+voxeo"/>
  </ask>
  <error type="modify">
    <bad-request xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/>
    <text xmlns="urn:ietf:params:xml:ns:xmpp-stanzas" lang="en">For choices, either 'url' or inline choices text is required (not both)</text>
  </error>
</iq>

When we place a Dial, the initial message back does not have a CallID, but instead a RefID and then builds the call out from there. The library needs to allow for outbound calls.

Ask should be able to take GRXML as a choices value. Both Ask and Say should be able to take SSML for the prompts.

https://gist.github.com/79981e49e5c1edb24c75

Jose has confirmed that the current 3s timeout on Ozone::Connection#write is not long enough. For example, might not return for 30s or so.

As such, we need to make sure Ozone::Connection#write can be done in a non-blocking way. We may still want to keep a timeout, but it should be much longer, perhaps configurable by the caller.

Per outbound calling here:

https://gist.github.com/3343fd5fd3b14b861e1b

It should probably not pass the attribute if not present. Wire.log, code and backtrace here:

https://gist.github.com/b916e059fa8cbb451314

Per this spec:

https://gist.github.com/3343fd5fd3b14b861e1b

Not Thor, as it is overkill. ;)

In order to be sure that the EventMachine is up and connected to XMPP for punchblock, we should fire an event to the event queue from the 'when_ready' callback handler in Blather.

This allows us to reduce the amount of routing and parsing we need to do.

This class here:

https://github.com/tropo/punchblock/blob/develop/lib/punchblock/call.rb

But, it does appear to break some downstream stuff (if I just switch to call_id in that class):

Exception in XMPP thread!



Call id cannot be null