Asterisk/UniMRCP Error on #ask when channel is not answered

[bklang]

I'm filing this here mostly for documentation, and to serve as the reference point for any upstream issues we choose to file.

I have an app using adhearsion-ivr with speech input. When attempting speech recognition on an incoming call, the Prompt component was crashing because of a fault returned by UniMRCP in Asterisk. The prompt response looks like this:

[2015-06-13 04:26:36.042] ERROR Adhearsion::Call: 73902b83-1922-41ce-a591-8facbd3df9ec@: <Adhearsion::Error> Punchblock::Translator::Asterisk::Component::MRCPRecogPrompt::UniMRCPError: #<Punchblock::Component::Prompt target_call_id="73902b83-1922-41ce-a591-8facbd3df9ec", target_mixer_name=nil, component_id="ef632e73-1c75-4304-930f-0ead8b6c9420", source_uri="ef632e73-1c75-4304-930f-0ead8b6c9420", domain=nil, transport=nil, timestamp=Sat, 13 Jun 2015 04:26:35 +0000, request_id="173035a6-5ddb-4735-bdc7-0408c5c78723", barge_in=true, output=#<Punchblock::Component::Output target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Sat, 13 Jun 2015 04:26:35 +0000, request_id="969dc79a-d4e1-4883-a309-bcf3d8fc2deb", headers={}, voice=nil, interrupt_on=nil, start_offset=nil, start_paused=nil, repeat_interval=nil, repeat_times=nil, max_time=nil, renderer="unimrcp", render_documents=[#<Punchblock::Component::Output::Document target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Sat, 13 Jun 2015 04:26:35 +0000, url=nil, content_type="application/ssml+xml", value=<speak xmlns="http://www.w3.org/2001/10/synthesis" version="1.0" xml:lang="en-US">To repeat choices, say Repeat, or press the star key</speak>>]>, input=#<Punchblock::Component::Input target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Sat, 13 Jun 2015 04:26:35 +0000, request_id="1820878e-5991-42e2-b704-67e035dba1e0", headers={"Speech-Complete-Timeout"=>2000, "DTMF-Terminate-Timeout"=>2000}, max_silence=10000, min_confidence=0.6, mode=:voice, recognizer="unimrcp", language="en-US", terminator=nil, sensitivity=nil, initial_timeout=10000, inter_digit_timeout=2000, recognition_timeout=nil, grammars=[#<Punchblock::Component::Input::Grammar target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Sat, 13 Jun 2015 04:26:35 +0000, value=nil, content_type=nil, url="http://10.203.175.51:8080/grammars/corporate_ivr/main_menu">, #<Punchblock::Component::Input::Grammar target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Sat, 13 Jun 2015 04:26:35 +0000, value=nil, content_type=nil, url="http://10.203.175.51:8080/grammars/corporate_ivr/main_menu_dtmf">]>>
    /var/lib/gems/2.2.0/gems/adhearsion-2.6.0/lib/adhearsion/call_controller.rb:224:in `execute_component_and_await_completion'
    /home/vagrant/.bundler/ruby/2.2.0/adhearsion-asr-d9a68fb8c81f/lib/adhearsion-asr/prompt_builder.rb:32:in `execute'
    /home/vagrant/.bundler/ruby/2.2.0/adhearsion-asr-d9a68fb8c81f/lib/adhearsion-asr/controller_methods.rb:49:in `ask'
    /home/vagrant/.bundler/ruby/2.2.0/adhearsion-ivr-33f215037b31/lib/adhearsion-ivr/ivr_controller.rb:159:in `deliver_prompt'
    /home/vagrant/.bundler/ruby/2.2.0/adhearsion-ivr-33f215037b31/lib/adhearsion-ivr/ivr_controller.rb:130:in `run'
    /var/lib/gems/2.2.0/gems/adhearsion-2.6.0/lib/adhearsion/call_controller.rb:119:in `execute!'
    /var/lib/gems/2.2.0/gems/adhearsion-2.6.0/lib/adhearsion/call_controller.rb:94:in `block in exec'
    /var/lib/gems/2.2.0/gems/adhearsion-2.6.0/lib/adhearsion/call_controller.rb:93:in `catch'
    /var/lib/gems/2.2.0/gems/adhearsion-2.6.0/lib/adhearsion/call_controller.rb:93:in `exec'
    /var/lib/gems/2.2.0/gems/adhearsion-2.6.0/lib/adhearsion/call_controller.rb:110:in `exec_with_callback'
    /var/lib/gems/2.2.0/gems/adhearsion-2.6.0/lib/adhearsion/call_controller.rb:104:in `block (2 levels) in bg_exec'
    /var/lib/gems/2.2.0/gems/adhearsion-2.6.0/lib/adhearsion/foundation/exception_handler.rb:5:in `catching_standard_errors'
    /var/lib/gems/2.2.0/gems/adhearsion-2.6.0/lib/adhearsion/call_controller.rb:103:in `block in bg_exec'
    /var/lib/gems/2.2.0/gems/celluloid-0.15.2/lib/celluloid/thread_handle.rb:13:in `block in initialize'
    /var/lib/gems/2.2.0/gems/celluloid-0.15.2/lib/celluloid/internal_pool.rb:100:in `call'
    /var/lib/gems/2.2.0/gems/celluloid-0.15.2/lib/celluloid/internal_pool.rb:100:in `block in create'
    /var/lib/gems/2.2.0/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `call'
    /var/lib/gems/2.2.0/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'

On the Asterisk side, two errors and one warning were logged by UniMRCP:

[Jun 13 04:26:35] ERROR[23950][C-00000003]: speech_channel.c:726 speech_channel_write: Speech channel structure pointer is NULL.
[Jun 13 04:26:35] ERROR[23950][C-00000003]: app_synthandrecog.c:691 recog_channel_get_results: (ASR-3) Recognition terminated prematurely
[Jun 13 04:26:35] WARNING[23950][C-00000003]: app_synthandrecog.c:1616 app_synthandrecog_exec: (ASR-3) Unable to retrieve result

The error message is generated by this code:

/* Write synthesized speech / speech to be recognized. */
int speech_channel_write(speech_channel_t *schannel, void *data, apr_size_t *len)
{
        int status = 0;

        if ((schannel != NULL) && *len != 0) {
                // Code elided: write speech data to channel
        } else {
                ast_log(LOG_ERROR, "Speech channel structure pointer is NULL.\n");
                return -1;
        }

By adding debug logging to UniMRCP I was able to determine that the problem wasn't actually that schannel was null, but instead len was 0. This was the clue that made me realize that the channel was not answered, thus an empty voice frame was attempting to be written.

Workaround

I added this to the top of my AdhearsionIVR::CallController

before_call { answer }

This is because AdhearsionIVR does not auto-answer the channel. We won't fix this in AdhearsionIVR because it probably shouldn't auto-answer, in case someone wants to use early media.

The real fix will have to come upstream from UniMRCP since it is failing to recognize if the channel is not answered, but also not logging any useful error message to that effect.