No INVITE Being Sent For TTS

[erj]

Hi Arsen,
    We've had some unusual behaviour on some of our servers, it looks like for TTS the stack isn't sending the INVITE so we see this in the logs:

2022-06-09 15:57:14:063561 [INFO] Create Channel MRCP-41167 <new>
2022-06-09 15:57:14:063561 [INFO] Receive App Request MRCP-41167 <new> [2]
2022-06-09 15:57:14:063561 [INFO] Add MRCP Handle MRCP-41167 <new>
2022-06-09 15:57:14:063561 [NOTICE] Add Control Channel MRCP-41167 <new@speechsynth>

When it does send the INVITE we see this:

2022-06-09 10:08:35:270563 [INFO] Create Channel MRCP-40806 <new>
2022-06-09 10:08:35:270563 [INFO] Receive App Request MRCP-40806 <new> [2]
2022-06-09 10:08:35:270563 [INFO] Add MRCP Handle MRCP-40806 <new>
2022-06-09 10:08:35:270563 [NOTICE] Add Control Channel MRCP-40806 <new@speechsynth>
2022-06-09 10:08:35:279571 [INFO] Send Offer MRCP-40806 <new> [c:1 a:1 v:0] to 10.32.53.102:5060
2022-06-09 10:08:35:279571 [INFO] Local SDP MRCP-40806 <new>
v=0
o=UniMRCPClient 0 0 IN IP4 10.0.145.8
s=-
c=IN IP4 10.0.145.8
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechsynth
a=cmid:1
m=audio 4036 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=recvonly
a=ptime:20
a=mid:1

So when it's not working we don't see the "Send Offer" log entry which I believe means that the code isn't calling the mrcp_client_session_offer_send function.

Looking at the mrcp_client_channel_add function we add the following:

1. We call mrcp_client_control_channel_add to add the channel and set waiting_for_channel to true and increment the static session->subrequest_count.
2. We call mpf_engine_termination_message_add and set waiting_for_termination to true and increment the static session->subrequest_count.
3. We call mpf_engine_termination_message_add again and set slot->waiting to true and increment the static session->subrequest_count.

The callback function for 1. is:
apt_bool_t mrcp_client_on_channel_add(mrcp_channel_t *channel, mrcp_control_descriptor_t *descriptor, apt_bool_t status)
{
    mrcp_client_session_t *session = (mrcp_client_session_t*)channel->session;
    apt_obj_log(APT_LOG_MARK,APT_PRIO_DEBUG,session->base.log_obj,"Control Channel Added " APT_NAMESIDRES_FMT,
                    MRCP_SESSION_NAMESID(session),
                    channel->resource->name.buf);
    if(!channel->waiting_for_channel) {
        return FALSE;
    }
    channel->waiting_for_channel = FALSE;
    if(mrcp_client_session_subrequest_remove(session) == TRUE) {
        /* send offer to server */
        mrcp_client_session_offer_send(session);
    }
    return TRUE;
}

The callback function for 2 and 3 is:
static apt_bool_t mrcp_client_on_termination_add(mrcp_client_session_t *session, const mpf_message_t *mpf_message)
{
    rtp_termination_slot_t *termination_slot;
    apt_obj_log(APT_LOG_MARK,APT_PRIO_DEBUG,session->base.log_obj,"Media Termination Added " APT_NAMESIDRES_FMT,
        MRCP_SESSION_NAMESID(session),
        mpf_termination_name_get(mpf_message->termination));
    termination_slot = mrcp_client_rtp_termination_find(session,mpf_message->termination);
    if(termination_slot) {
        /* rtp termination */
        mpf_rtp_termination_descriptor_t *rtp_descriptor;
        if(termination_slot->waiting == FALSE) {
            return FALSE;
        }
        termination_slot->waiting = FALSE;
        rtp_descriptor = mpf_message->descriptor;
        if(rtp_descriptor->audio.local) {
            session->offer->ip = rtp_descriptor->audio.local->ip;
            session->offer->ext_ip = rtp_descriptor->audio.local->ext_ip;
            rtp_descriptor->audio.local->id = mrcp_session_audio_media_add(session->offer,rtp_descriptor->audio.local);
            rtp_descriptor->audio.local->mid = session->offer->audio_media_arr->nelts;
            termination_slot->id = session->offer->audio_media_arr->nelts - 1;
        }
        if(mrcp_client_session_subrequest_remove(session) == TRUE) {
            /* send offer to server */
            mrcp_client_session_offer_send(session);
        }
    }
    else {
        /* channel termination */
        mrcp_channel_t *channel = mrcp_client_channel_termination_find(session,mpf_message->termination);
        if(channel && channel->waiting_for_termination == TRUE) {
            channel->waiting_for_termination = FALSE;
            if(mrcp_client_session_subrequest_remove(session) == TRUE) {
                /* send offer to server */
                mrcp_client_session_offer_send(session);
            }
        }
    }
    return TRUE;
}

Given that the callbacks are decoupled from the function calls then is it guaranteed to always call mrcp_client_session_offer_send ? If all three function calls were made before any of the callbacks were called then I think the 'if(termination_slot)' would be true twice and the second time it would come out on 'if(termination_slot->waiting == FALSE)' and never call mrcp_client_session_offer_send. Is that possible ?

Is it worth changing 'if(termination_slot)' to 'if(termination_slot && (termination_slot->waiting == TRUE))' ?

Any help would be gratefully received.

Thanks
Ed James

[Arsen Chaloyan]

Hi Ed,

It would be hard to identify the problem without having the DEBUG logs. Here is the regular sequence of statements that should normally be logged.

This is where it starts.

[NOTICE] Add Control Channel umc-1 <new@speechrecog>

As a result, async messages are sent to sub-tasks:

• Media-Engine1: to add two media terminations
• MRCPv2-Agent: to add a control channel

The order of the statements is not guaranteed but the general logic should be the same. More importantly, you should check for "Signal Message to [MRCP Client]", which later would be processed by the client task with the statements "Process Message [MRCP Client]".

[DEBUG]  Process Poller Wakeup [MRCPv2-Agent-1]

[DEBUG]  Add Media Termination umc-1 <new@media-tm>
[DEBUG]  Add Media Termination umc-1 <new@rtp-tm>
[DEBUG]  Process Message [MRCPv2-Agent-1] [0x9e70c8;1;0]
[DEBUG]  Signal Message to [Media-Engine-1] [0x32a6d00;1;0]
[DEBUG]  Wait for Messages [MRCP Client]
[DEBUG]  Signal Message to [MRCP Client] [0x9e71b8;2;0]
[DEBUG]  Wait for Messages [MRCPv2-Agent-1]
[DEBUG]  Process Message [MRCP Client] [0x9e71b8;2;0]
[DEBUG]  Control Channel Added umc-1 <new@speechrecog>
[DEBUG]  Wait for Messages [MRCP Client]
[DEBUG]  Process Message [Media-Engine-1] [0x32a6d00;1;0]
[DEBUG]  Signal Message to [MRCP Client] [0x32a6dd0;3;0]
[DEBUG]  Process Message [MRCP Client] [0x32a6dd0;3;0]
[DEBUG]  Media Termination Added umc-1 <new@media-tm>
[DEBUG]  Media Termination Added umc-1 <new@rtp-tm>

Once the pending responses are received, an offer will be sent out to the signaling agent.

[INFO]   Send Offer umc-1 <new> [c:1 a:1 v:0] to 10.10.0.20:8060

> If all three function calls were made before any of the callbacks were called then I think the 'if(termination_slot)' would be true twice and the second time it would come out on 'if(termination_slot->waiting == FALSE)' and never call mrcp_client_session_offer_send. Is that possible ?

Sorry, if I am not following you right, but there are two different termination_slot objects here. Each has its own waiting flag.

--
You received this message because you are subscribed to the Google Groups "UniMRCP" group.
To unsubscribe from this group and stop receiving emails from it, send an email to unimrcp+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/unimrcp/6d5b9e85-a997-4cf0-ab32-865b58354d09n%40googlegroups.com.

--

Arsen Chaloyan
Author of UniMRCP
http://www.unimrcp.org