3845 IVR fails but 2821 works..why?

Version 1
    This document was generated from CDN thread

    Created by: LEON MCCALLA on 06-06-2012 10:18:13 AM
    below is a “deb voip appl media” debug for a call into debit.tcl. The exact same script work on my 2821. please tell me what is causing this failure. I’ve highlited the area in red that I suspect is causing the problem but I’m not sure whats going on. When I dial into the 3845 using SIP I get connected but there is no audio. if I dial-into the 2821 I get the prompts.

    Please help..

    Leon



    445692: Jun 6 10:10:42.861: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445693: Jun 6 10:10:43.409: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445694: Jun 6 10:10:43.609: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445695: Jun 6 10:10:43.689: //14423148//Dest:/DestStartMediaNegotiation: MediaNeg not supported for this module
    445696: Jun 6 10:10:43.897: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445697: Jun 6 10:10:44.117: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445698: Jun 6 10:10:45.617: //14423184//Dest:/DestStartMediaNegotiation: MediaNeg not supported for this module
    445699: Jun 6 10:10:46.137: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445700: Jun 6 10:10:46.325: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445701: Jun 6 10:10:46.541: //-1//DPM P56:/pc_mc_createDynamicS: calloc mcDynamicS_t
    445702: Jun 6 10:10:46.541: //-1//DPM P56:/pc_mc_addToDynamicS: (1) _enter_dest.au
    445703: Jun 6 10:10:46.541: //-1//DPM P56:/pc_mc_addToDynamicS: Doing : _enter_dest.au
    445704: Jun 6 10:10:46.541: //-1//DPM :/mcTokenizerGetNext: savedcharptr=_ endptrptr=_enter_dest.au
    445705: Jun 6 10:10:46.541: //-1//DPM P56:/pc_mc_addToDynamicS: Token : _enter_dest.au status 1
    445706: Jun 6 10:10:46.541: //-1//DPM P56:/pc_mc_addToDynamicS: call dp_mcDQfromFileDynamic() to Handle relative file name

    445707: Jun 6 10:10:46.541: //-1//DPM P56:/dp_mcDQfromFileDynamic: pLanguage=en FileName=_enter_dest.au
    445708: Jun 6 10:10:46.541: //-1//DPM P56:/dp_mcDQfromURL: file=tftp://172.16.0.2/prompts/g729/en_enter_dest.au
    445709: Jun 6 10:10:46.541: //-1//MCM :/mc_createFromFileUrl: Getting a media content: name=en_enter_dest.au
    url=tftp://172.16.0.2/prompts/g729/en_enter_dest.au
    load fast, fetchtimeout=-1
    445710: Jun 6 10:10:46.541: //-1//MCM :MC9:/mc_getFromUrlName: en_enter_dest.au on ram
    445711: Jun 6 10:10:46.541: //-1//MCM :MC9:/mc_waitq_unlink: elm=70CE41A0
    445712: Jun 6 10:10:46.541: //-1//MCM :MC9:/mc_waitq_unlink: prompt_wait=3552 prompt_active=0

    445713: Jun 6 10:10:46.541: //-1//MCM :MC9:/mc_waitq_delete: prompt_wait=3552 prompt_active=97E
    445714: Jun 6 10:10:46.541: //-1//MCM :/mc_createFromFileUrl: Found a good mc (0x71240FA8), RefCount(1)
    445715: Jun 6 10:10:46.541: //-1//DPM P56:/dp_mcDQfromURL: mc_createFromFileUrl OK
    445716: Jun 6 10:10:46.541: //-1//DPM :LPP56:MC9:/dp_mcDQfromURL:
    445717: Jun 6 10:10:46.541: dp_mcDQfromURL enqueuing en_enter_dest.au OK###
    445718: Jun 6 10:10:46.541: //-1//DPM :/mcTokenizerGetNext: savedcharptr= endptrptr=
    445719: Jun 6 10:10:46.541: //14423286//MSW :/msw_create: cbf=0x623074A8
    445720: Jun 6 10:10:46.541: //-1//MSM :MS35:/ms_create: Iniz ply_timer
    445721: Jun 6 10:10:46.541: //14423286//MSW :/msw_synth_open: mediaStream 0x70D5ABB8 created
    445722: Jun 6 10:10:46.541: //14423286//MSW :/msw_synth_open: rtspStream 0x67708064 created,
    status=RTSP_STATUS_SUCCESS, session_id=0x23 (35)
    445723: Jun 6 10:10:46.541: //14423286//MSW :/msw_synth_open: AIS : Creating TTS AIS Backend record
    445724: Jun 6 10:10:46.541: //-1//MSM :MS36:/ms_create: Iniz ply_timer
    445725: Jun 6 10:10:46.541: //14423286//MSW :/msw_recrd_open:
    445726: Jun 6 10:10:46.541: :msw_recrd_open mediaStream 0xC08FDB44 created
    445727: Jun 6 10:10:46.541: //14423286//MSW :/msw_recrd_open: rtspStream 0x6770806C created,
    status=RTSP_STATUS_SUCCESS, session_id=0x24 (36)
    445728: Jun 6 10:10:46.541: //14423286//MSW :/msw_recog_open: AIS : Creating ASR AIS Backend record
    445729: Jun 6 10:10:46.541: //-1//MSW :/msw_associate_call:
    445730: Jun 6 10:10:46.541: msw_associate_call: callID=0xDC14F6(14423286),
    genericStream=0x7078BB70
    445731: Jun 6 10:10:46.541: //14423286//MSW :/msw_synth_get_stream_state: genericStream 0x7078BB70 is in state MSW_S_IDLE
    445732: Jun 6 10:10:46.541: //-1//MSW :/msw_synth_start:
    445733: Jun 6 10:10:46.541: msw_synth_start: Enter...
    445734: Jun 6 10:10:46.541: //14423286//MSW :/msw_synth_start: current_stream_id=1, content 0x0, dynamicS 0xC0E3AA7C, current_state=MSW_S_IDLE
    445735: Jun 6 10:10:46.541: //-1//MSW :/msw_synth_start: msw_synth_start: p_mcDynamicS, We've been given a list of URLs to play.
    445736: Jun 6 10:10:46.541: //-1//MSW :/msw_synth_start: p_mcDynamicQ is NOT empty
    445737: Jun 6 10:10:46.541: //14423286//MSW :/msu_synth_partial_play: Media Stream URL
    445738: Jun 6 10:10:46.541: //-1//MCM :MR55:/mc_createDynamicReader:
    445739: Jun 6 10:10:46.541: //14423286//MSM :/ms_get_packet_size:
    445740: Jun 6 10:10:46.541: ms_get_packet_size NO Voice Class codec
    445741: Jun 6 10:10:46.541: //14423286//MSM :/ms_associate: packet_size = 40 timestamp increment = 320 packet_duration = 40 Coder = 16 vad = 0 SampleRate = 8000
    445742: Jun 6 10:10:46.541: //14423286//MSM :/ms_associate: >>ccAssociateStream()
    445743: Jun 6 10:10:46.545: //14423286//MSM :LP:MS35:/ms_associateDone:
    445744: Jun 6 10:10:46.545: //14423286//MSM :/ms_asDone_buginf: callID=0xDC14F6, pVdb=0x67704678,
    disposition=-5, playFunc=0x62ED07B8,
    codec=0x10=g729r8, vad=0,
    mediaType=3, streamAssocID=14423287
    445745: Jun 6 10:10:46.545: //14423286//MSM :/ms_asDone_buginf: Stream Association Failed: Requested codec=0x10=g729r8, Negotiated codec=0x10=g729r8
    445746: Jun 6 10:10:46.545: //14423286//MSM :/ms_stop_play: mgdTstop at 5w2d (cause MS_STOP_SETUPFAIL)
    445747: Jun 6 10:10:46.545: //14423286//MSM :/ms_stop_play: Play Stopped at 5w2d
    445748: Jun 6 10:10:46.545: //14423286//MSM :/ms_stop_play: calling CBF for stream_id 1
    445749: Jun 6 10:10:46.545: //14423286//MSW :/msu_synth_ms_play_complete: context=0x7078BB74, use_dynamic=1, dynamicElement=0x70CE41A0,
    cause=MS_STOP_SETUPFAIL, stream_id=1, duration=0, rate=0 proto_code=0
    445750: Jun 6 10:10:46.545: //14423286//MSW :/msu_synth_ms_play_complete:
    445751: Jun 6 10:10:46.545: //14423286//MSW :/msu_call_app: app_cbf=0x623074A8
    Event = MSW_EV_SYNTHESIZER(1), Context 0x715BD634, Type MSW_SYNTH_TYPE_SYNTHESIZE(2), Reason MSW_SYNTH_REASON_SETUPFAIL(12)
    445752: Jun 6 10:10:46.545: //-1//MSW :/msw_mediadone_stats:
    445753: Jun 6 10:10:46.545: //-1//DPM P56:/dp_delete_mcDynamicS: >dequeue(mcDynamicQ)
    445754: Jun 6 10:10:46.545: //-1//MCM :MC9:/mc_delete: mc=0x71240FA8
    445755: Jun 6 10:10:46.545: //-1//MCM :MC9:/mc_delete: refCount=1
    445756: Jun 6 10:10:46.545: //-1//MCM :MC9:/mc_check_background_load: mc(0x71240FA8), mc->eof=1
    445757: Jun 6 10:10:46.545: //-1//MCM :MC9:/mc_waitq_add: prompt_wait=3ED0 prompt_active=0
    445758: Jun 6 10:10:46.545: //-1//DPM P56:/dp_delete_mcDynamicS: >free(p_mcDynamicS)
    445759: Jun 6 10:10:46.545: //-1//MCM :MR55:/mc_delete_read: dequeue(pakList)
    445760: Jun 6 10:10:46.549: //14423286//AFW_:/AFW_FSM_Drive: FSM no match for (GETDEST[7],ev_media_done[162])
    445761: Jun 6 10:10:47.249: //14423261//Dest:/DestStartMediaNegotiation: MediaNeg not supported for this module
    445762: Jun 6 10:10:48.197: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445763: Jun 6 10:10:48.425: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445764: Jun 6 10:10:48.501: //14423253//Dest:/DestStartMediaNegotiation: MediaNeg not supported for this module
    445765: Jun 6 10:10:48.709: //14423208//Dest:/DestStartMediaNegotiation: MediaNeg not supported for this module
    445766: Jun 6 10:10:48.981: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445767: Jun 6 10:10:49.121: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445768: Jun 6 10:10:49.709: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445769: Jun 6 10:10:51.189: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445770: Jun 6 10:10:51.397: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445771: Jun 6 10:10:51.649: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445772: Jun 6 10:10:52.293: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445773: Jun 6 10:10:52.489: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445774: Jun 6 10:10:54.377: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445775: Jun 6 10:10:54.549: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445776: Jun 6 10:10:54.617: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445777: Jun 6 10:10:54.785: //14423286//MSW :/msw_destroy:
    445778: Jun 6 10:10:54.785: //-1//MSW :/msw_stop: genericStream=0x7078BB70,
    reason=MSW_REASON_DISCONNECTED
    445779: Jun 6 10:10:54.785: //-1//MSW :/msw_synth_stop: msw_synth_stop: Enter...
    445780: Jun 6 10:10:54.785: //-1//MSW :/msw_synth_stop: genericStream=0x7078BB70,
    mediaStream=0x70D5ABB8, rtspStream=0x67708064
    reason=MSW_SYNTH_REASON_DISCONNECTED, current_state=MSW_S_IDLE
    445781: Jun 6 10:10:54.785: //14423286//MSW :/msw_synth_stop: Stream not currently active
    445782: Jun 6 10:10:54.785: //-1//MSW :/msw_recrd_stop: genericStream=0x7078BB70,
    mediaStream=0xC08FDB44, rtspStream=0x6770806C
    reason=MSW_RECRD_REASON_DISCONNECTED current_state=MSW_S_IDLE
    445783: Jun 6 10:10:54.785: //-1//MSW :/msw_recrd_stop: Stream not currently active
    445784: Jun 6 10:10:54.785: //-1//MSW :/msw_recog_stop:
    445785: Jun 6 10:10:54.785: msw_recog_stop: genericStream=0x7078BB70,
    mrcpStream=0xC03D8A8C
    reason=MSW_RECOG_REASON_DISCONNECTED, current_state=MSW_S_IDLE
    445786: Jun 6 10:10:54.785: //-1//MSW :/msw_synth_stop: msw_synth_stop: Enter...
    445787: Jun 6 10:10:54.785: //-1//MSW :/msw_synth_stop: genericStream=0x7078BB70,
    mediaStream=0x70D5ABB8, rtspStream=0x67708064
    reason=MSW_SYNTH_REASON_DISCONNECTED, current_state=MSW_S_IDLE
    445788: Jun 6 10:10:54.785: //14423286//MSW :/msw_synth_stop: Stream not currently active
    445789: Jun 6 10:10:54.785: //-1//MSW :/msw_recrd_stop: genericStream=0x7078BB70,
    mediaStream=0xC08FDB44, rtspStream=0x6770806C
    reason=MSW_RECRD_REASON_DISCONNECTED current_state=MSW_S_IDLE
    445790: Jun 6 10:10:54.785: //-1//MSW :/msw_recrd_stop: Stream not currently active
    445791: Jun 6 10:10:54.785: //-1//MSW :/msw_recog_stop:
    445792: Jun 6 10:10:54.785: msw_recog_stop: genericStream=0x7078BB70,
    mrcpStream=0xC03D8A8C
    reason=MSW_RECOG_REASON_DISCONNECTED, current_state=MSW_S_IDLE
    445793: Jun 6 10:10:55.257: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)
    445794: Jun 6 10:10:55.477: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not found for tag(56)

    Subject: RE: 3845 IVR fails but 2821 works..why?
    Replied by: LEON MCCALLA on 07-06-2012 05:57:16 AM
    445745: Jun 6 10:10:46.545: //14423286//MSM :/ms_asDone_buginf: Stream Association Failed: Requested codec=0x10=g729r8, Negotiated codec=0x10=g729r8
    445746: Jun 6 10:10:46.545: //14423286//MSM :/ms_stop_play: mgdTstop at 5w2d (cause MS_STOP_SETUPFAIL)


    Its the same codec. same script, same config on both Routers....

    Leon

    Subject: RE: 3845 IVR fails but 2821 works..why?
    Replied by: Anusha Kannappan on 07-06-2012 05:13:55 AM
    Hi Leon,

    Please cross check whether there is any mismatch in codec.

    Thanks,
    Anusha

    Subject: RE: 3845 IVR fails but 2821 works..why?
    Replied by: Anusha Kannappan on 07-06-2012 07:28:45 AM
    Hi Leon,

    Try to reload the prompts also check the audio files are same. If still issue persists share the IOS version of the passing and failing cases.

    Thanks,
    Anusha

    Subject: RE: 3845 IVR fails but 2821 works..why?
    Replied by: LEON MCCALLA on 07-06-2012 09:10:07 AM
    The 2801 is my dev router.  "flash:c2801-ipvoicek9-mz.151-4.M1.bin"
    the 3845 is for production ..  "flash:c3845-ipvoice_ivs-mz.124-24.T3.bin"
     
    IP-IVR should work on both.
     
    Leon

    Subject: RE: 3845 IVR fails but 2821 works..why?
    Replied by: Anusha Kannappan on 08-06-2012 07:31:37 AM
    Hi Leon,

    As we don't see any application related issue over here, we have passed the information to the DE team. Once I get an update I shall share the same with you.

    Thanks,
    Anusha

    Subject: RE: 3845 IVR fails but 2821 works..why?
    Replied by: Anusha Kannappan on 11-06-2012 05:16:52 AM
    Hi Leon,

    Our DE team needs the information on the IVR scenario, and what’s failing. Also collect the following debug from the router.

                    Debug voip app
      Debug voip  app vxml
                    Debug voip app vxml dump
                    Debug voip ccapi default
                    Debug mrcp all
                    Debug rtsp socket

    Please post the script,running config along with debugs or send it to developer-support@cisco.com to analyze the issue further.


    Thanks,
    Anusha

    Subject: Re: New Message from Anusha Kannappan in Voice Gateway API (VGAPI) - TCL-AP
    Replied by: LEON MCCALLA on 04-09-2012 10:36:10 AM
    Anusha,
    any news on this bug? if you give me the bugID I’ll follow up on it on my own..

    Leon

    From: Cisco Developer Community Forums
    Sent: Monday, June 11, 2012 5:16 AM
    To: cdicuser@developer.cisco.com
    Subject: New Message from Anusha Kannappan in Voice Gateway API (VGAPI) - TCL-API: RE: 3845 IVR fails but 2821 works..why?

    Anusha Kannappan has created a new message in the forum "TCL-API":

    --------------------------------------------------------------
    Hi Leon,

    Our DE team needs the information on the IVR scenario, and what’s failing. Also collect the following debug from the router.

    Debug voip app
    Debug voip app vxml
    Debug voip app vxml dump
    Debug voip ccapi default
    Debug mrcp all
    Debug rtsp socket

    Please post the script,running config along with debugs or send it to developer-support@cisco.com to analyze the issue further.


    Thanks,
    Anusha
    --
    To respond to this post, please click the following link:

    <http://developer.cisco.com/web/vgapi/forums/-/message_boards/view_message/5846614>

    or simply reply to this email.

    Subject: RE: 3845 IVR fails but 2821 works..why?
    Replied by: Anusha Kannappan on 05-09-2012 02:32:53 AM
    Hi Leon,

    Apologize for the delay ! We are yet to receive the updates from our DE team. Will surely get back to you once I get an update from them.

    Thanks,
    Anusha

    Subject: RE: 3845 IVR fails but 2821 works..why?
    Replied by: Anusha Kannappan on 06-09-2012 01:31:06 AM
    Hi Leon,

    Our DE team are saying that as the debugs were collected from console (not from buffer), several debugs are lost and can't say what codec was negotiated on the incoming call. Please collect the logs from logging buffer with the following debugs enabled for 3845 router which is having issue rather than 3745 as it has been EOLed.

    debug voip ccapi def
    debug voip app

    Thanks,
    Anusha