This document was generated from CDN thread
Created by: Chris Manuh on 01-11-2012 09:13:32 AM
I have a TCL script that uses 'leg setup' to make an outbound call. Once the call is connected it, plays a pre-recorded message to the caller and disconnects. The script works on our development environment. however, when we deployed the script on our client's network, we noticed that "leg setup" always returns ls_000 status at about 4seconds, and usually long before the phone actually starts ringing and before the caller actually picks up the call. So to the TCL script, since "leg setup" has already returned success, the script has started playing the message. so if the person picks up the call, they don't hear the beginning of the message. Any suggestions or ideas on how to address this is greatly appreciated.
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 01-11-2012 11:47:49 AM
It's hard to tell without seeing log, configuration and script, is it possible to attach them ? At least call setup part of script.
Thanks
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 07-11-2012 07:54:00 PM
Do you havelog for
deb voip app tcl
deb voip app scr
?
I don't think it's psoobile t rell what's going on by only seeing this log and two lines of script.
<h2>If you don't like to post you script here you can send it to [email protected]</h2>
Thanks !
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 07-11-2012 06:52:56 PM
Here's a log (Telephone number replaced with 9905977XXXX):
7148619: Nov 8 00:00:32.415:
7148620: Nov 8 00:00:32.415: //-1//TCL :EE44BB83A4000:/tcl_PutsObjCmd: action_http_request_complete - complete
7148621: Nov 8 00:00:32.415:
7148622: Nov 8 00:00:33.163: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_begin:
Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
Source Call Id=969250, Digit=6, DigitBeginFlags=0x0,
Rtp Timestamp=0x85061298, Rtp Expiration=0x0
7148623: Nov 8 00:00:33.163: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_end:
Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
Source Call Id=969250, Digit=6, Duration=100,
Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
7148624: Nov 8 00:00:33.163: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_end:
Call Entry(Handoff Depth=0)
7148625: Nov 8 00:00:33.351: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_begin:
Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
Source Call Id=969250, Digit=6, DigitBeginFlags=0x0,
Rtp Timestamp=0x85068F98, Rtp Expiration=0x0
7148626: Nov 8 00:00:33.351: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_end:
Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
Source Call Id=969250, Digit=6, Duration=100,
Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
7148627: Nov 8 00:00:33.351: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_end:
Call Entry(Handoff Depth=0)
7148628: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_begin:
Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
Source Call Id=969250, Digit=4, DigitBeginFlags=0x0,
Rtp Timestamp=0x85070C98, Rtp Expiration=0x0
7148629: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_end:
Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
Source Call Id=969250, Digit=4, Duration=100,
Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
7148630: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_end:
Call Entry(Handoff Depth=0)
7148631: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCallReportDigits:
(callID=0xECA22, digit_event=0x0, enable=FALSE, consume=FALSE)
7148632: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCallReportDigits:
Enabled=TRUE, Call Id=969250
7148633: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_api_call_report_digits_done:
(vdbPtr=0x442EF460, callID=0xECA22, disp=0, digit_event=0x0, enable=FALSE, consume=FALSE)
7148634: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_api_call_report_digits_done:
Enabled=TRUE, Disposition=0x0, Interface=0x442EF460, Call Id=969250
7148635: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_api_call_report_digits_done:
Call Entry(Initial Digit Timeout=15000(ms), Inter Digit Timeout=10000(ms))
7148636: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCallProceeding:
Progress Indication=NULL(0)
7148637: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCallSetupRequest:
Destination=, Calling IE Present=TRUE, Mode=0,
Outgoing Dial-peer=10, Params=0x11EBA0F4, Progress Indication=ORIGINATING SIDE IS NON ISDN(3)
7148638: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_fill_tg_params:
Not a cic call
7148639: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCallSetupRequest:
Trunk Group Select Interface Success;
Interface=0x1535C108, Selected Interface=1, Selected DSL=-1
7148640: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCheckClipClir:
In: Calling Number=2000(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
7148641: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCheckClipClir:
Out: Calling Number=2000(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
7148642: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCallSetupRequest:
Destination Pattern=9[2-9]..[2-9]......$, Called Number=9905977XXXX, Digit Strip=TRUE
7148643: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCallSetupRequest:
Calling Number=2000(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
Called Number=9905977XXXX(TON=Unknown, NPI=Unknown),
Redirect Number=, Display Info=Main Reception
Account Number=, Final Destination Flag=FALSE,
Guid=22F9126D-286E-11E2-BBF3-9037F7B46B81, Outgoing Dial-peer=10
7148644: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_api_display_ie_subfields:
ccCallSetupRequest:
cisco-username=
----- ccCallInfo IE subfields -----
cisco-ani=2000
cisco-anitype=0
cisco-aniplan=0
cisco-anipi=0
cisco-anisi=0
dest=9905977XXXX
cisco-desttype=0
cisco-destplan=0
cisco-rdie=FFFFFFFF
cisco-rdn=
cisco-rdntype=0
cisco-rdnplan=0
cisco-rdnpi=0
cisco-rdnsi=0
cisco-redirectreason=0 fwd_final_type =0
final_redirectNumber =
hunt_group_timeout =0
7148645: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccIFCallSetupRequestPrivate:
Interface=0x1535C108, Interface Type=6, Destination=, Mode=0x0,
Call Params(Calling Number=2000,(Calling Name=Main Reception)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentati
on=Allowed),
Called Number=9905977XXXX(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
Subscriber Type Str=RegularLine, FinalDestinationFlag=FALSE, Outgoing Dial-peer=10, Call Count On=FALSE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=OUTBOUND, tg_label_flag=2, Application Call Id=)
7148646: Nov 8 00:00:33.683: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
7148647: Nov 8 00:00:33.683: :cc_get_feature_vsa malloc success
7148648: Nov 8 00:00:33.683: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
7148649: Nov 8 00:00:33.683: cc_get_feature_vsa count is 3
7148650: Nov 8 00:00:33.683: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
7148651: Nov 8 00:00:33.683: :FEATURE_VSA attributes are: feature_name:0,feature_time:328741704,feature_id:1948093
7148652: Nov 8 00:00:33.683: //969251/22F9126DBBF3/CCAPI/ccIFCallSetupRequestPrivate:
SPI Call Setup Request Is Success; Interface Type=6, FlowMode=1
7148653: Nov 8 00:00:33.687: //969250/22F9126DBBF3/CCAPI/ccCallSetupRequest:
Trunk Group Call Setting;
Call Entry(Retry Count=0, Voice Class Cause Code=0)
7148654: Nov 8 00:00:33.687: //969251/22F9126DBBF3/CCAPI/ccCallSetContext:
Context=0x11EBA0A4
7148655: Nov 8 00:00:33.687: //969250/22F9126DBBF3/CCAPI/ccSaveDialpeerTag:
Outgoing Dial-peer=10
7148656: Nov 8 00:00:33.687: //969250/22F9126DBBF3/CCAPI/cc_api_modify_tgt_cid_call_active_record:
Target Trkgrp Route Label=OUTBOUND, tg_label_flag=TRUE, Call Id=0xECA22
7148657: Nov 8 00:00:33.687: //969251/22F9126DBBF3/CCAPI/cc_api_call_proceeding:
Interface=0x1535C108, Progress Indication=NULL(0)
7148658: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/cc_api_call_cut_progress:
Interface=0x1535C108, Progress Indication=INBAND(8), Signal Indication=INTERCEPT(2),
Cause Value=0
7148659: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/cc_api_call_cut_progress:
Call Entry(Responsed=TRUE)
7148660: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/ccCallCutProgress:
Progress Indication=INBAND(8), Signal Indication=INTERCEPT(2), Cause Value=0
Voice Call Send Alert=FALSE, Call Entry(Alert Sent=FALSE)
7148661: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/ccCallCutProgress:
Call Entry(Responsed=TRUE)
7148662: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/ccGenerateToneInfo:
Stop Tone On Digit=FALSE, Tone=Null,
Tone Direction=Network, Params=0x0, Call Id=969250
7148663: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/ccConferenceCreate:
(confID=0x3A68104, callID1=0xECA22, gcid=22F9126D-286E11E2-BBF39037-F7B46B81, tag=0x0)
7148664: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/ccConferenceCreate:
(confID=0x3A68104, callID2=0xECA23, gcid=22F9126D-286E11E2-BBF39037-F7B46B81, tag=0x0)
7148665: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/ccConferenceCreate:
Conference Id=0x3A68104, Call Id1=969250, Call Id2=969251, Tag=0x0
7148666: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/cc_api_bridge_done:
Conference Id=0x5736D, Source Interface=0x442EF460, Source Call Id=969250,
Destination Call Id=969251, Disposition=0x0, Tag=0xFFFFFFFF
7148667: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/cc_api_bridge_done:
Conference Id=0x5736D, Source Interface=0x1535C108, Source Call Id=969251,
Destination Call Id=969250, Disposition=0x0, Tag=0xFFFFFFFF
7148668: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/cc_generic_bridge_done:
Conference Id=0x5736D, Source Interface=0x1535C108, Source Call Id=969251,
Destination Call Id=969250, Disposition=0x0, Tag=0xFFFFFFFF
7148669: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/ccConferenceCreate:
Call Entry(Conference Id=0x5736D, Destination Call Id=969251)
7148670: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/ccConferenceCreate:
Call Entry(Conference Id=0x5736D, Destination Call Id=969250)
7148671: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/cc_api_caps_ind:
Destination Interface=0x1535C108, Destination Call Id=969251, Source Call Id=969250,
Caps(Codec=0x1, Fax Rate=0x2, Vad=0x1,
Modem=0x2, Codec Bytes=160, Signal Type=2)
7148672: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/cc_api_caps_ind:
Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
Playout Max=1000(ms), Fax Nom=300(ms))
7148673: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/cc_api_caps_ind:
Destination Interface=0x442EF460, Destination Call Id=969250, Source Call Id=969251,
Caps(Codec=0x1, Fax Rate=0x1, Vad=0x1,
Modem=0x2, Codec Bytes=160, Signal Type=2)
7148674: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/cc_api_caps_ind:
Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
Playout Max=1000(ms), Fax Nom=300(ms))
7148675: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/cc_api_caps_ack:
Destination Interface=0x442EF460, Destination Call Id=969250, Source Call Id=969251,
Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Vad=OFF(0x1),
Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=3925)
7148676: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/cc_api_caps_ack:
Destination Interface=0x1535C108, Destination Call Id=969251, Source Call Id=969250,
Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_NONE(0x1), Vad=OFF(0x1),
Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=1712)
7148677: Nov 8 00:00:37.319: //969250/22F9126DBBF3/CCAPI/ccCallFeature:
Feature Type=25, Call Id=969250
7148678: Nov 8 00:00:37.319: //969250/22F9126DBBF3/CCAPI/cc_api_voice_mode_event:
Call Id=969250
7148679: Nov 8 00:00:37.319: //969250/22F9126DBBF3/CCAPI/cc_api_voice_mode_event:
Call Entry(Context=0x1200D228)
7148680: Nov 8 00:00:37.319: //969251/22F9126DBBF3/CCAPI/cc_api_voice_mode_event:
Call Id=969251
7148681: Nov 8 00:00:37.319: //969251/22F9126DBBF3/CCAPI/cc_api_voice_mode_event:
Call Entry(Context=0x11EBA0A4)
7148682: Nov 8 00:00:37.319: //969251/22F9126DBBF3/CCAPI/cc_api_call_connected:
Interface=0x1535C108, Data Bitmask=0x1, Progress Indication=DESTINATION IS NON ISDN(2),
Connection Handle=0
7148683: Nov 8 00:00:37.319: //969251/22F9126DBBF3/CCAPI/cc_api_call_connected:
Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)
7148684: Nov 8 00:00:37.319: //969250/22F9126DBBF3/CCAPI/cc_process_notify_bridge_done:
Conference Id=0x5736D, Call Id1=969250, Call Id2=969251
7148685: Nov 8 00:00:37.319: //969250/22F9126DBBF3/CCAPI/ccCallConnect:
Progress Indication=DESTINATION IS NON ISDN(2), Data Bitmask=0x1
7148686: Nov 8 00:00:37.319: //969250/22F9126DBBF3/CCAPI/ccCallConnect:
Call Entry(Connected=TRUE, Responsed=TRUE)
7148687: Nov 8 00:00:37.319: //969250/22F9126DBBF3/CCAPI/ccCallFeature:
Feature Type=25, Call Id=969250
7148688: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_api_call_disconnected:
Cause Value=16, Interface=0x442EF460, Call Id=969250
7148689: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_api_call_disconnected:
Call Entry(Responsed=TRUE, Cause Value=16, Retry Count=0)
7148690: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/ccConferenceDestroy:
Conference Id=0x5736D, Tag=0x0
7148691: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_api_bridge_drop_done:
Conference Id=0x5736D, Source Interface=0x442EF460, Source Call Id=969250,
Destination Call Id=969251, Disposition=0x0, Tag=0x0
7148692: Nov 8 00:01:04.975: //969251/22F9126DBBF3/CCAPI/cc_api_bridge_drop_done:
Conference Id=0x5736D, Source Interface=0x1535C108, Source Call Id=969251,
Destination Call Id=969250, Disposition=0x0, Tag=0x0
7148693: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_generic_bridge_done:
Conference Id=0x5736D, Source Interface=0x1535C108, Source Call Id=969251,
Destination Call Id=969250, Disposition=0x0, Tag=0x0
7148694: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/ccCallDisconnect:
Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=16)
7148695: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/ccCallDisconnect:
Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
7148696: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_api_get_transfer_info:
Transfer Number Is Null
7148697: Nov 8 00:01:04.975: //969251/22F9126DBBF3/CCAPI/ccCallDisconnect:
Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
7148698: Nov 8 00:01:04.975: //969251/22F9126DBBF3/CCAPI/ccCallDisconnect:
Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
7148699: Nov 8 00:01:04.975: //969251/22F9126DBBF3/CCAPI/cc_api_get_transfer_info:
Transfer Number Is Null
7148700: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_api_call_feature:
Feature Type=6, Interface=0x442EF460, Call Id=969250
7148701: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x442EF460, Tag=0x0, Call Id=969250,
Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
7148702: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
7148703: Nov 8 00:01:04.975: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
7148704: Nov 8 00:01:04.975: :cc_free_feature_vsa freeing 13983180
7148705: Nov 8 00:01:04.975: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
7148706: Nov 8 00:01:04.975: vsacount in free is 2
7148707: Nov 8 00:01:04.995: //969251/22F9126DBBF3/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x1535C108, Tag=0x0, Call Id=969251,
Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
7148708: Nov 8 00:01:04.995: //969251/22F9126DBBF3/CCAPI/cc_api_call_disconnect_done:
tg for this call is OUTBOUND success/fail is 1
7148709: Nov 8 00:01:04.995: //969251/22F9126DBBF3/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
7148710: Nov 8 00:01:04.995: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
7148711: Nov 8 00:01:04.995: :cc_free_feature_vsa freeing 13983340
7148712: Nov 8 00:01:04.995: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
7148713: Nov 8 00:01:04.995: vsacount in free is 1
----------------------------------
Leg setup looks as show below. the $phone number is initialized with a value before the call
set call_info(alertTime) 30
leg setup $phone call_info
----------------------------------
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 09-11-2012 12:23:15 AM
Hi Yaw,
Here's the log and a simplified script
Subject: RE: Leg setup command returns before call is connected
Replied by: Anusha Kannappan on 09-11-2012 04:42:07 AM
Hi Chris,
I had tried your sample app by replacing the vxml stuff with a normal media file since had issue TTS and it worked properly with the follwoing changes in FSM
set fsm(SETUP,ev_setup_indication) "action_setup same_state"
set fsm(any_state,ev_media_done) "action_voice_dialog_complete same_state"
Is it possible to check the same whether it is working fine for normal audio file first so that it would be easy to isolate the issue. Even if it is not working for normal audio file, please share the logs along with the IOS version being used in this case.
Thanks,
Anusha
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 09-11-2012 10:46:42 AM
Yes, the script does work but the issue is that the ios seems to accept the call, then establish another connection leg on its own and joins the two calls. from all the tests i've done, it happens always at a 4second mark from the time leg setup is issued to when it returns to my script with status ls_000. meanwhile, the actual call hasn't actually been answered yet so the script plays the message to dead air. if the message is long and the user picks up, they'll hear just the middle or end of the message.
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 09-11-2012 11:52:26 AM
ls_000 is a trigger event. I can think of two posibilties here.
1. far end is "connected"
2. IOS sned Tcl application false setup done event whick I think it's unlikely.
Two things we can try here
1. replace destination with a phone and let it ring forever see if there is setup done event sent.
2. debug underline protocol see if there is any "CONNECT", "200 OK" ... message sent from far end
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 09-11-2012 12:50:21 PM
The logs i posted was from last night. This is a log capture from the service provider (from october 25), when we thought the issue might be on their end. The connected status is reported after about 1minute, but our TCL script reported success at about 4 seconds. MakeCall request was made at Oct 25 21:41:51 and connected at Oct 25 21:42:08.
------------------------------
<!--[if gte mso 9]><xml>
<w:WordDocument>
<w
iew>Normal</wiew>
<w:Zoom>0</w:Zoom>
<w:TrackMoves />
<w:TrackFormatting />
<w
unctuationKerning />
<walidateAgainstSchemas />
<w:SaveIfXMLInvalid>false</w:SaveIfXMLInvalid>
<w:IgnoreMixedContent>false</w:IgnoreMixedContent>
<w:AlwaysShowPlaceholderText>false</w:AlwaysShowPlaceholderText>
<w
oNotPromoteQF />
<w:LidThemeOther>EN-US</w:LidThemeOther>
<w:LidThemeAsian>X-NONE</w:LidThemeAsian>
<w:LidThemeComplexScript>X-NONE</w:LidThemeComplexScript>
<w:Compatibility>
<w:BreakWrappedTables />
<w:SnapToGridInCell />
<w:WrapTextWithPunct />
<w:UseAsianBreakRules />
<wontGrowAutofit />
<w:SplitPgBreakAndParaMark />
<w:EnableOpenTypeKerning />
<wontFlipMirrorIndents />
<w
verrideTableStyleHps />
</w:Compatibility>
<w:BrowserLevel>MicrosoftInternetExplorer4</w:BrowserLevel>
<m:mathPr>
<m:mathFont m:val="Cambria Math" />
<m:brkBin m:val="before" />
<m:brkBinSub m:val="--" />
<m:smallFrac m:val="off" />
<m:dispDef />
<m:lMargin m:val="0" />
<m:rMargin m:val="0" />
<m:defJc m:val="centerGroup" />
<m:wrapIndent m:val="1440" />
<m:intLim m:val="subSup" />
<m:naryLim m:val="undOvr" />
</m:mathPr></w:WordDocument>
</xml><!-->
<!--[if gte mso 9]><xml>
<w:LatentStyles DefLockedState="false" DefUnhideWhenUsed="true"
DefSemiHidden="true" DefQFormat="false" DefPriority="99"
LatentStyleCount="267">
<w:LsdException Locked="false" Priority="0" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Normal" />
<w:LsdException Locked="false" Priority="9" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="heading 1" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 2" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 3" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 4" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 5" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 6" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 7" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 8" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 9" />
<w:LsdException Locked="false" Priority="39" Name="toc 1" />
<w:LsdException Locked="false" Priority="39" Name="toc 2" />
<w:LsdException Locked="false" Priority="39" Name="toc 3" />
<w:LsdException Locked="false" Priority="39" Name="toc 4" />
<w:LsdException Locked="false" Priority="39" Name="toc 5" />
<w:LsdException Locked="false" Priority="39" Name="toc 6" />
<w:LsdException Locked="false" Priority="39" Name="toc 7" />
<w:LsdException Locked="false" Priority="39" Name="toc 8" />
<w:LsdException Locked="false" Priority="39" Name="toc 9" />
<w:LsdException Locked="false" Priority="35" QFormat="true" Name="caption" />
<w:LsdException Locked="false" Priority="10" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Title" />
<w:LsdException Locked="false" Priority="1" Name="Default Paragraph Font" />
<w:LsdException Locked="false" Priority="11" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Subtitle" />
<w:LsdException Locked="false" Priority="22" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Strong" />
<w:LsdException Locked="false" Priority="20" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Emphasis" />
<w:LsdException Locked="false" Priority="59" SemiHidden="false"
UnhideWhenUsed="false" Name="Table Grid" />
<w:LsdException Locked="false" UnhideWhenUsed="false" Name="Placeholder Text" />
<w:LsdException Locked="false" Priority="1" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="No Spacing" />
<w:LsdException Locked="false" Priority="60" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Shading" />
<w:LsdException Locked="false" Priority="61" SemiHidden="false"
UnhideWhenUsed="false" Name="Light List" />
<w:LsdException Locked="false" Priority="62" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Grid" />
<w:LsdException Locked="false" Priority="63" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 1" />
<w:LsdException Locked="false" Priority="64" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 2" />
<w:LsdException Locked="false" Priority="65" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 1" />
<w:LsdException Locked="false" Priority="66" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 2" />
<w:LsdException Locked="false" Priority="67" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 1" />
<w:LsdException Locked="false" Priority="68" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 2" />
<w:LsdException Locked="false" Priority="69" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 3" />
<w:LsdException Locked="false" Priority="70" SemiHidden="false"
UnhideWhenUsed="false" Name="Dark List" />
<w:LsdException Locked="false" Priority="71" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Shading" />
<w:LsdException Locked="false" Priority="72" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful List" />
<w:LsdException Locked="false" Priority="73" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Grid" />
<w:LsdException Locked="false" Priority="60" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Shading Accent 1" />
<w:LsdException Locked="false" Priority="61" SemiHidden="false"
UnhideWhenUsed="false" Name="Light List Accent 1" />
<w:LsdException Locked="false" Priority="62" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Grid Accent 1" />
<w:LsdException Locked="false" Priority="63" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 1 Accent 1" />
<w:LsdException Locked="false" Priority="64" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 2 Accent 1" />
<w:LsdException Locked="false" Priority="65" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 1 Accent 1" />
<w:LsdException Locked="false" UnhideWhenUsed="false" Name="Revision" />
<w:LsdException Locked="false" Priority="34" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="List Paragraph" />
<w:LsdException Locked="false" Priority="29" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Quote" />
<w:LsdException Locked="false" Priority="30" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Intense Quote" />
<w:LsdException Locked="false" Priority="66" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 2 Accent 1" />
<w:LsdException Locked="false" Priority="67" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 1 Accent 1" />
<w:LsdException Locked="false" Priority="68" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 2 Accent 1" />
<w:LsdException Locked="false" Priority="69" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 3 Accent 1" />
<w:LsdException Locked="false" Priority="70" SemiHidden="false"
UnhideWhenUsed="false" Name="Dark List Accent 1" />
<w:LsdException Locked="false" Priority="71" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Shading Accent 1" />
<w:LsdException Locked="false" Priority="72" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful List Accent 1" />
<w:LsdException Locked="false" Priority="73" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Grid Accent 1" />
<w:LsdException Locked="false" Priority="60" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Shading Accent 2" />
<w:LsdException Locked="false" Priority="61" SemiHidden="false"
UnhideWhenUsed="false" Name="Light List Accent 2" />
<w:LsdException Locked="false" Priority="62" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Grid Accent 2" />
<w:LsdException Locked="false" Priority="63" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 1 Accent 2" />
<w:LsdException Locked="false" Priority="64" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 2 Accent 2" />
<w:LsdException Locked="false" Priority="65" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 1 Accent 2" />
<w:LsdException Locked="false" Priority="66" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 2 Accent 2" />
<w:LsdException Locked="false" Priority="67" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 1 Accent 2" />
<w:LsdException Locked="false" Priority="68" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 2 Accent 2" />
<w:LsdException Locked="false" Priority="69" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 3 Accent 2" />
<w:LsdException Locked="false" Priority="70" SemiHidden="false"
UnhideWhenUsed="false" Name="Dark List Accent 2" />
<w:LsdException Locked="false" Priority="71" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Shading Accent 2" />
<w:LsdException Locked="false" Priority="72" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful List Accent 2" />
<w:LsdException Locked="false" Priority="73" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Grid Accent 2" />
<w:LsdException Locked="false" Priority="60" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Shading Accent 3" />
<w:LsdException Locked="false" Priority="61" SemiHidden="false"
UnhideWhenUsed="false" Name="Light List Accent 3" />
<w:LsdException Locked="false" Priority="62" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Grid Accent 3" />
<w:LsdException Locked="false" Priority="63" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 1 Accent 3" />
<w:LsdException Locked="false" Priority="64" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 2 Accent 3" />
<w:LsdException Locked="false" Priority="65" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 1 Accent 3" />
<w:LsdException Locked="false" Priority="66" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 2 Accent 3" />
<w:LsdException Locked="false" Priority="67" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 1 Accent 3" />
<w:LsdException Locked="false" Priority="68" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 2 Accent 3" />
<w:LsdException Locked="false" Priority="69" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 3 Accent 3" />
<w:LsdException Locked="false" Priority="70" SemiHidden="false"
UnhideWhenUsed="false" Name="Dark List Accent 3" />
<w:LsdException Locked="false" Priority="71" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Shading Accent 3" />
<w:LsdException Locked="false" Priority="72" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful List Accent 3" />
<w:LsdException Locked="false" Priority="73" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Grid Accent 3" />
<w:LsdException Locked="false" Priority="60" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Shading Accent 4" />
<w:LsdException Locked="false" Priority="61" SemiHidden="false"
UnhideWhenUsed="false" Name="Light List Accent 4" />
<w:LsdException Locked="false" Priority="62" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Grid Accent 4" />
<w:LsdException Locked="false" Priority="63" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 1 Accent 4" />
<w:LsdException Locked="false" Priority="64" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 2 Accent 4" />
<w:LsdException Locked="false" Priority="65" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 1 Accent 4" />
<w:LsdException Locked="false" Priority="66" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 2 Accent 4" />
<w:LsdException Locked="false" Priority="67" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 1 Accent 4" />
<w:LsdException Locked="false" Priority="68" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 2 Accent 4" />
<w:LsdException Locked="false" Priority="69" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 3 Accent 4" />
<w:LsdException Locked="false" Priority="70" SemiHidden="false"
UnhideWhenUsed="false" Name="Dark List Accent 4" />
<w:LsdException Locked="false" Priority="71" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Shading Accent 4" />
<w:LsdException Locked="false" Priority="72" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful List Accent 4" />
<w:LsdException Locked="false" Priority="73" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Grid Accent 4" />
<w:LsdException Locked="false" Priority="60" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Shading Accent 5" />
<w:LsdException Locked="false" Priority="61" SemiHidden="false"
UnhideWhenUsed="false" Name="Light List Accent 5" />
<w:LsdException Locked="false" Priority="62" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Grid Accent 5" />
<w:LsdException Locked="false" Priority="63" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 1 Accent 5" />
<w:LsdException Locked="false" Priority="64" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 2 Accent 5" />
<w:LsdException Locked="false" Priority="65" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 1 Accent 5" />
<w:LsdException Locked="false" Priority="66" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 2 Accent 5" />
<w:LsdException Locked="false" Priority="67" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 1 Accent 5" />
<w:LsdException Locked="false" Priority="68" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 2 Accent 5" />
<w:LsdException Locked="false" Priority="69" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 3 Accent 5" />
<w:LsdException Locked="false" Priority="70" SemiHidden="false"
UnhideWhenUsed="false" Name="Dark List Accent 5" />
<w:LsdException Locked="false" Priority="71" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Shading Accent 5" />
<w:LsdException Locked="false" Priority="72" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful List Accent 5" />
<w:LsdException Locked="false" Priority="73" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Grid Accent 5" />
<w:LsdException Locked="false" Priority="60" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Shading Accent 6" />
<w:LsdException Locked="false" Priority="61" SemiHidden="false"
UnhideWhenUsed="false" Name="Light List Accent 6" />
<w:LsdException Locked="false" Priority="62" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Grid Accent 6" />
<w:LsdException Locked="false" Priority="63" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 1 Accent 6" />
<w:LsdException Locked="false" Priority="64" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 2 Accent 6" />
<w:LsdException Locked="false" Priority="65" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 1 Accent 6" />
<w:LsdException Locked="false" Priority="66" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 2 Accent 6" />
<w:LsdException Locked="false" Priority="67" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 1 Accent 6" />
<w:LsdException Locked="false" Priority="68" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 2 Accent 6" />
<w:LsdException Locked="false" Priority="69" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 3 Accent 6" />
<w:LsdException Locked="false" Priority="70" SemiHidden="false"
UnhideWhenUsed="false" Name="Dark List Accent 6" />
<w:LsdException Locked="false" Priority="71" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Shading Accent 6" />
<w:LsdException Locked="false" Priority="72" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful List Accent 6" />
<w:LsdException Locked="false" Priority="73" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Grid Accent 6" />
<w:LsdException Locked="false" Priority="19" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Subtle Emphasis" />
<w:LsdException Locked="false" Priority="21" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Intense Emphasis" />
<w:LsdException Locked="false" Priority="31" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Subtle Reference" />
<w:LsdException Locked="false" Priority="32" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Intense Reference" />
<w:LsdException Locked="false" Priority="33" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Book Title" />
<w:LsdException Locked="false" Priority="37" Name="Bibliography" />
<w:LsdException Locked="false" Priority="39" QFormat="true" Name="TOC Heading" />
</w:LatentStyles>
</xml><!--><!--[if gte mso 10]>
<mce:style><!
/* Style Definitions */
table.MsoNormalTable
{mso-style-name:"Table Normal";
mso-tstyle-rowband-size:0;
mso-tstyle-colband-size:0;
mso-style-noshow:yes;
mso-style-priority:99;
mso-style-parent:"";
mso-padding-alt:0cm 5.4pt 0cm 5.4pt;
mso-para-margin:0cm;
mso-para-margin-bottom:.0001pt;
mso-pagination:widow-orphan;
font-size:10.0pt;
font-family:"Times New Roman","serif";}
-->
<!-- -->
Oct 25 21:41:48 10.21.221.62 CommandDigitInterface [001D] L9 - Event Reset(Tone=eNORMAL, bAcceptCallWaitingPossible=0, bSwitchCallsPossible=0, bEndActiveCallPossibl
e=0, bConferencePossible=0, bCallTransferPossible=0) on state "FINAL"
Oct 25 21:41:48 10.21.221.62 CommandDigitInterface [001E] L9 - Event Reset was not handled by state "FINAL", send the event to his parent "ROOT"
Oct 25 21:41:48 10.21.221.62 CommandDigitInterface [001F] L9 - Change state from "FINAL" to "INITIAL"
Oct 25 21:41:48 10.21.221.62 CommandDigitInterface [0020] L9 - Change state from "INITIAL" to "IDLE"
Oct 25 21:41:48 10.21.221.62 FxsInterface [0021] L9 - Change state from "CONTROL WAIT PERMISSION" to "CONTROL MODE"
Oct 25 21:41:48 10.21.221.62 AnalogEndpoint [0022] OffHookDetected change mode to Call Setup on EP9
Oct 25 21:41:48 10.21.221.62 AnalogLine [0023] iPlayToneA - Tone 0, Endpoint 9
Oct 25 21:41:48 10.21.221.62 AnalogEndpoint [0024] LowPlayTone EP9, DIALTONE, Tone Country: NorthAmerica1 Tone, tone info 0x2
Oct 25 21:41:48 10.21.221.62 AnalogLine [0025] Hapiecan_state DSP1, op1:0x3 op2:0x1c80
Oct 25 21:41:48 10.21.221.62 PotsEndpoint [0026] EP 9 HHEvent - NetVHD mode change event op1:2 op2:0 Call Setup.
Oct 25 21:41:49 10.21.221.62 PotsEndpoint [0027] EP 9 HHEvent - Dialed digit detected 1.
Oct 25 21:41:49 10.21.221.62 FxsInterface [0028] L9 - Event DtmfDetect(1) on state "CONTROL MODE"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [0029] L9 - Event Dtmf(1) on state "IDLE"
Oct 25 21:41:49 10.21.221.62 AnalogLine [002A] iStopToneA - Endpoint 9
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [002B] L9 - Change state from "IDLE" to "DTMF"
Oct 25 21:41:49 10.21.221.62 PotsEndpoint [002C] EP 9 HHEvent - DTMF Off 1.
Oct 25 21:41:49 10.21.221.62 FxsInterface [002D] L9 - Event DtmfTerminated(1) on state "CONTROL MODE"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [002E] L9 - Event DtmfOff(1) on state "DTMF"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [002F] L9 - Event DtmfOff(1) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [0030] L9 - Event DtmfOff(1) was not handled
Oct 25 21:41:49 10.21.221.62 PotsEndpoint [0031] EP 9 HHEvent - Dialed digit detected 9.
Oct 25 21:41:49 10.21.221.62 FxsInterface [0032] L9 - Event DtmfDetect(9) on state "CONTROL MODE"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [0033] L9 - Event Dtmf(9) on state "DTMF"
Oct 25 21:41:49 10.21.221.62 PotsEndpoint [0034] EP 9 HHEvent - DTMF Off 9.
Oct 25 21:41:49 10.21.221.62 FxsInterface [0035] L9 - Event DtmfTerminated(9) on state "CONTROL MODE"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [0036] L9 - Event DtmfOff(9) on state "DTMF"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [0037] L9 - Event DtmfOff(9) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [0038] L9 - Event DtmfOff(9) was not handled
Oct 25 21:41:49 10.21.221.62 PotsEndpoint [0039] EP 9 HHEvent - Dialed digit detected 0.
Oct 25 21:41:49 10.21.221.62 FxsInterface [003A] L9 - Event DtmfDetect(0) on state "CONTROL MODE"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [003B] L9 - Event Dtmf(0) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [003C] EP 9 HHEvent - DTMF Off 0.
Oct 25 21:41:50 10.21.221.62 FxsInterface [003D] L9 - Event DtmfTerminated(0) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [003E] L9 - Event DtmfOff(0) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [003F] L9 - Event DtmfOff(0) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0040] L9 - Event DtmfOff(0) was not handled
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [0041] EP 9 HHEvent - Dialed digit detected 5.
Oct 25 21:41:50 10.21.221.62 FxsInterface [0042] L9 - Event DtmfDetect(5) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0043] L9 - Event Dtmf(5) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [0044] EP 9 HHEvent - DTMF Off 5.
Oct 25 21:41:50 10.21.221.62 FxsInterface [0045] L9 - Event DtmfTerminated(5) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0046] L9 - Event DtmfOff(5) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0047] L9 - Event DtmfOff(5) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0048] L9 - Event DtmfOff(5) was not handled
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [0049] EP 9 HHEvent - Dialed digit detected 9.
Oct 25 21:41:50 10.21.221.62 FxsInterface [004A] L9 - Event DtmfDetect(9) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [004B] L9 - Event Dtmf(9) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [004C] EP 9 HHEvent - DTMF Off 9.
Oct 25 21:41:50 10.21.221.62 FxsInterface [004D] L9 - Event DtmfTerminated(9) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [004E] L9 - Event DtmfOff(9) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [004F] L9 - Event DtmfOff(9) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0050] L9 - Event DtmfOff(9) was not handled
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [0051] EP 9 HHEvent - Dialed digit detected 4.
Oct 25 21:41:50 10.21.221.62 FxsInterface [0052] L9 - Event DtmfDetect(4) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0053] L9 - Event Dtmf(4) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [0054] EP 9 HHEvent - DTMF Off 4.
Oct 25 21:41:50 10.21.221.62 FxsInterface [0055] L9 - Event DtmfTerminated(4) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0056] L9 - Event DtmfOff(4) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0057] L9 - Event DtmfOff(4) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0058] L9 - Event DtmfOff(4) was not handled
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [0059] EP 9 HHEvent - Dialed digit detected 9.
Oct 25 21:41:50 10.21.221.62 FxsInterface [005A] L9 - Event DtmfDetect(9) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [005B] L9 - Event Dtmf(9) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [005C] EP 9 HHEvent - DTMF Off 9.
Oct 25 21:41:50 10.21.221.62 FxsInterface [005D] L9 - Event DtmfTerminated(9) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [005E] L9 - Event DtmfOff(9) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [005F] L9 - Event DtmfOff(9) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0060] L9 - Event DtmfOff(9) was not handled
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [0061] EP 9 HHEvent - Dialed digit detected 0.
Oct 25 21:41:50 10.21.221.62 FxsInterface [0062] L9 - Event DtmfDetect(0) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0063] L9 - Event Dtmf(0) on state "DTMF"
Oct 25 21:41:51 10.21.221.62 PotsEndpoint [0064] EP 9 HHEvent - DTMF Off 0.
Oct 25 21:41:51 10.21.221.62 FxsInterface [0065] L9 - Event DtmfTerminated(0) on state "CONTROL MODE"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0066] L9 - Event DtmfOff(0) on state "DTMF"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0067] L9 - Event DtmfOff(0) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0068] L9 - Event DtmfOff(0) was not handled
Oct 25 21:41:51 10.21.221.62 PotsEndpoint [0069] EP 9 HHEvent - Dialed digit detected 1.
Oct 25 21:41:51 10.21.221.62 FxsInterface [006A] L9 - Event DtmfDetect(1) on state "CONTROL MODE"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [006B] L9 - Event Dtmf(1) on state "DTMF"
Oct 25 21:41:51 10.21.221.62 PotsEndpoint [006C] EP 9 HHEvent - DTMF Off 1.
Oct 25 21:41:51 10.21.221.62 FxsInterface [006D] L9 - Event DtmfTerminated(1) on state "CONTROL MODE"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [006E] L9 - Event DtmfOff(1) on state "DTMF"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [006F] L9 - Event DtmfOff(1) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0070] L9 - Event DtmfOff(1) was not handled
Oct 25 21:41:51 10.21.221.62 PotsEndpoint [0071] EP 9 HHEvent - Dialed digit detected 3.
Oct 25 21:41:51 10.21.221.62 FxsInterface [0072] L9 - Event DtmfDetect(3) on state "CONTROL MODE"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0073] L9 - Event Dtmf(3) on state "DTMF"
Oct 25 21:41:51 10.21.221.62 PotsEndpoint [0074] EP 9 HHEvent - DTMF Off 3.
Oct 25 21:41:51 10.21.221.62 FxsInterface [0075] L9 - Event DtmfTerminated(3) on state "CONTROL MODE"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0076] L9 - Event DtmfOff(3) on state "DTMF"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0077] L9 - Event DtmfOff(3) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0078] L9 - Event DtmfOff(3) was not handled
Oct 25 21:41:51 10.21.221.62 PotsEndpoint [0079] EP 9 HHEvent - Dialed digit detected 9.
Oct 25 21:41:51 10.21.221.62 FxsInterface [007A] L9 - Event DtmfDetect(9) on state "CONTROL MODE"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [007B] L9 - Event Dtmf(9) on state "DTMF"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [007C] L9 - Change state from "DTMF" to "FINAL"
190594901301:51 10.21.221.62 FxsInterface [007D] L9 - Event MakeCall(
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [007E] L9 - Event Terminate() on state "FINAL"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [007F] L9 - Event Terminate was not handled by state "FINAL", send the event to his parent "ROOT"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0080] L9 - Change state from "FINAL" to "FINAL"
Oct 25 21:41:51 10.21.221.62 FxsInterface [0081] L9 - Change state from "CONTROL MODE" to "CONTROL WAITING RESPONSE"
Oct 25 21:41:51 10.21.221.62 CallManager [0082] L9 UI9 MakeCallA - source #SIP#sme2.mtncbl.net,0,HAM14-NHCH-9055231184-01,| | destination #TEL#19059490130|.
Oct 25 21:41:51 10.21.221.62 CallManager [0083] InternalMakeCallA - ILineApprovalManager::ApproveLineToProtocolCall returned eLINE_APPROVED.
Oct 25 21:41:51 10.21.221.62 CallManager [0084] L9 UI9 CCallTable::AddCall | ACTIVE 1: 247076.
Oct 25 21:41:51 10.21.221.62 CallManager [0085] L9 C247076 InternalMakeCallA - InviteA event sent | source #SIP#sme2.mtncbl.net,0,HAM14-NHCH-9055231184-01,| | destination #TEL#19059490130|.
Oct 25 21:41:51 10.21.221.62 CallManager [0086] L9 InternalMakeCallA - CallUpdatedA event sent.
Oct 25 21:41:51 10.21.221.62 CallManager [0087] L9 UI9 ReleaseControlA.
Oct 25 21:41:51 10.21.221.62 FxsInterface [0088] L9 - Event CallUpdated(3075EEB8) on state "CONTROL WAITING RESPONSE"
Oct 25 21:41:51 10.21.221.62 SipEngine [0089] CCallCxMgr::Invite L9 C247076
Oct 25 21:41:51 10.21.221.62 SipEngine [008A] CCallCxMgr::Create L9 C247076
Oct 25 21:41:51 10.21.221.62 CRtpEngine [008B] CRtpConnection::SelectSessionMode() - Success - mode = 0, - AID9, CID247076
Oct 25 21:41:51 10.21.221.62 CRtpEngine [008C] CRtpPacketizer::ModifySettings() - encoding = PCMU, payload size = 160, SID size = 0, TS inc. = 15
Oct 25 21:41:51 10.21.221.62 CRtpEngine [008D] CRtpConnection::SelectCompressionAlgorithm() - Success - payload = PCMU ptime = 20, - AID9, CID247076
Oct 25 21:41:51 10.21.221.62 CRtpEngine [008E] CRtcpSession:pen() - Enter
Oct 25 21:41:51 10.21.221.62 CRtpEngine [008F] CUdpSocket::Create() - Success
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0090] CUdpSocket::Bind() - Success - 0.0.0.0:5005
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0091] CRtcpSession:pen() - Exit
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0092] CRtpSession:pen() - Enter - AID9, SID247076
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0093] CUdpSocket::Create() - Success
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0094] CUdpSocket::Bind() - Success - 0.0.0.0:5004
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0095] CUdpSocket::Connect() - Success - 0.0.0.0:0
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0096] CUdpSocket::SetAllowAnySource() - Success
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0097] CUdpSocket::SetUdpChecksum() - Success
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0098] CUdpSocket::SetTos() - Success - Tos= 184
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0099] CUdpSocket::Set8021QUserPriority() - Success - Priority= 255
Oct 25 21:41:51 10.21.221.62 CRtpEngine [009A] CRtpSession:pen() - Success - AID9, SID247076
Oct 25 21:41:51 10.21.221.62 CRtpEngine [009B] CRtpConnection:pen() - Success - AID9, CID247076
Oct 25 21:41:51 10.21.221.62 CRtpEngine [009C] CRtpEngine:penConnection() - Success - AID9, CID247076
Oct 25 21:41:51 10.21.221.62 SipEngine [009D] L9 C247076 sending invite.
Oct 25 21:41:51 10.21.221.62 PotsEndpoint [009E] EP 9 HHEvent - DTMF Off 9.
Oct 25 21:41:51 10.21.221.62 FxsInterface [009F] L9 - Event DtmfTerminated(9) on state "CONTROL WAITING RESPONSE"
Oct 25 21:41:51 10.21.221.62 FxsInterface [00A0] L9 - Event DtmfTerminated was not handled by state "CONTROL WAITING RESPONSE", send the event to his parent "CONTROL COMPLEX"
Oct 25 21:41:51 10.21.221.62 FxsInterface [00A1] L9 - Event DtmfTerminated was not handled by state "CONTROL COMPLEX", send the event to his parent "ROOT"
Oct 25 21:41:51 10.21.221.62 FxsInterface [00A2] L9 - Event DtmfTerminated was not handled
Oct 25 21:41:54 10.21.220.211 SipEngine [1BAE] Sending response to out of dialog OPTIONS.
Oct 25 21:41:54 10.21.221.62 CallManager [00A3] L9 C247076 ProgressingA.
Oct 25 21:41:54 10.21.221.62 CallManager [00A4] L9 C247076 InternalProgressingA - CallStatusA event sent | call status eSTATUS_PROGRESSING.
Oct 25 21:41:54 10.21.221.62 FxsInterface [00A5] L9 - Event CallStatus(5) on state "CONTROL WAITING RESPONSE"
Oct 25 21:41:54 10.21.221.62 FxsInterface [00A6] L9 - Change state from "CONTROL WAITING RESPONSE" to "CONTROL RING"
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00A7] CRtpEngine::SetDynamicPayloadType() -EEncodingName 1, -PayloadType 96, - AID 9, CID 247076, - mode 2 SUCCESS
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00A8] CRtpSession::Modify() - Success - mode: 3 - realmode: 3 - AID9, SID247076
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00A9] CRtpConnection::SelectSessionMode() - Success - mode = 3, - AID9, CID247076
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00AA] CRtpPacketizer::ModifySettings() - encoding = PCMU, payload size = 160, SID size = 0, TS inc. = 15
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00AB] CUdpSocket::SetTos() - Success - Tos= 184
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00AC] CUdpSocket::Set8021QUserPriority() - Success - Priority= 255
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00AD] CRtpSession::Modify() - (Outgoing codec) - Success - payload: PCMU, ptime: 20 - AID9, SID247076
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00AE] CRtpConnection::SelectCompressionAlgorithm() - Success - payload = PCMU ptime = 20, - AID9, CID247076
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00AF] CRtpConnection::Modify() - (Connection) Success - AID9, CID247076
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00B0] CRtpEngine::ModifyConnection() - Success - AID9, CID247076
Oct 25 21:41:54 10.21.221.62 AnalogEndpoint [00B1] ReceivePacket - Endpoint 9 : Packet with wrong connection Id=247076 (can be normal if switching call - m_unCallId is 0).
Oct 25 21:41:54 10.21.221.62 AnalogLine [00B2] iStartVoiceCommunicationA- Endpoint 9, Algo 96 (0 if not specified)
Oct 25 21:41:54 10.21.221.62 AnalogEndpoint [00B3] EP9 SetRuntimeOptions (old-new) (T38=0-0, CCCodec=0x60-0x60, MCEDin=0-0,MCEDout=0-0, IgnCNG=0-0, IgnCED=0-0, CDIS=1-1, AleIgnCNG=0-0,AleIngCED=0-0)valid=1, (DtmfInBd=0-0)valid=1 (FlashRtpTx=1-1)valid=1 (FlashRtpRx=1-1)valid=1
Oct 25 21:41:54 10.21.221.62 AnalogEndpoint [00B4] GoInVoiceMode change mode to Packet Voice on EP9
Oct 25 21:41:54 10.21.221.62 AnalogLine [00B5] Hapiecan_state DSP1, op1:0x3 op2:0x1c80
Oct 25 21:41:54 10.21.221.62 PotsEndpoint [00B6] EP 9 HHEvent - NetVHD mode change event op1:3 op2:0 Packet Voice.
Oct 25 21:41:54 10.21.221.62 AnalogEndpoint [00B7] EP 9 Voice encoder rate change to 0x40a0
Oct 25 21:41:54 10.21.221.62 AnalogEndpoint [00B8] G.711 mu-law 64 kbps generic VAD
Oct 25 21:41:54 10.21.221.62 AnalogEndpoint [00B9] EP 9 Voice encoder rate change to 0x60
Oct 25 21:41:54 10.21.221.62 AnalogEndpoint [00BA] G.711 mu-law 64 kbps
Oct 25 21:42:08 10.21.221.62 25 21:42:5 10.21.221.62 CallManager [00BB] L9 C247076 AcceptedA.
Oct 25 21:42:08 10.21.221.62 25 21:42:5 10.21.221.62 CallManager [00BC] L9 C247076 InternalAcceptedA - ActivateMediaA event sent.
Oct 25 21:42:08 10.21.221.62 25 21:42:5 10.21.221.62 CallManager [00BD] L9 C247076 InternalAcceptedA - CallStatusA event sent | call status eSTATUS_CONNECTED.
Oct 25 21:42:08 10.21.221.62 25 21:42:5 10.21.221.62 FxsInterface [00BE] L9 - Event CallStatus(6) on state "CONTROL RING"
Oct 25 21:42:08 10.21.221.62 25 21:42:5 10.21.221.62 FxsInterface [00BF] L9 - Change state from "CONTROL RING" to "IN PROGRESS"
Oct 25 21:42:08 10.21.221.62 25 21:42:5 10.21.221.62 SipEngine [00C0] L9 C247076 session established.
Oct 25 21:42:08 10.21.221.62 25 21:42:5 10.21.221.62 SipEngine [00C1] CCallCxMgr::ActivateMedia L9 C247076
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 09-11-2012 01:02:56 PM
This is interesting/
What is the protocl ? Can we capture debug from GW ?
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 09-11-2012 03:04:40 PM
Are you referring to the voice gateway that the TCL is running from? if so then yes. we can capture debug logs. any specific debug you want to see?
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 09-11-2012 05:08:39 PM
I don't know what protocol is used between GW and destination. Please run the debug for that protocol plus
deb voip app tcl
deb voip app scr
deb voip ccapi inout
thanks
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 12-11-2012 09:50:05 PM
Hi Yaw,
Here's the log capture (Attached) of the script previously posted with the debugs turned on.
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 12-11-2012 10:35:35 PM
Do you know you client environment well ? what is on the other end ?
Is h323 trunk ? Is it possible to capture Wireshark log ?
Another thing to try is that try to add a phone call trigger (calling from phone to trigger script, ev_setup_indication). This may tell something
In really life do you really manulay start script ?
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 13-11-2012 01:41:53 PM
from what I've been told, the Cisco IOS router connects to a mediatrix sip endpoint with analog lines. The mediatrix connects to a softswitch at the telco side and the mediatrix and the softswitch talk sip but it's beyond my control.
The test i run was triggered manually from the console. in production, it'll be triggered from a timer via event manager. the app is an outbound dialer that calls 100s of people and deliver custom messages.
We interact with their gateway remotely so I don't think we'll be able to wireshark it.
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 13-11-2012 02:25:03 PM
Hi Yaw,
After checking with one of our cisco engineers, he says it may be possible to do wireshark remotely. Is there any thing in particular you want to capture?
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 13-11-2012 02:31:08 PM
mediatrix sip endpoint with analog lines
If it's analog, Wireshark is out of option. Is FXO or FXS ?
Cisco FXS---- FXO mediatrix sip endpoint ?
or
Cisco FXO --- FXS mediatrix sip endpoint ?
If it's SIP trunk we just need to turn
deb ccsip mess
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 14-11-2012 12:54:52 PM
TAC is right if there is a Tcl involved. They don't support.
But if it's not Tcl issue it could be far end, TAC cannot help much either.Just like Cisco Tcl IVR application, far end can connect call as soon as cll arrived.
Also we are not only deal with single componet,we don't know how they handle the incoming call.
" Cisco IOS router connects to a mediatrix sip endpoint with analog
lines. The mediatrix connects to a softswitch at the telco side and the
mediatrix and the softswitch talk sip but it's beyond my control."
If I was you I will do the follwoing:
1. find out the following, I remeber one of this direction may have some impact, like cannot detect on/off hook from FXS
If it's analog, Wireshark is out of option. Is FXO or FXS ?
Cisco FXS---- FXO mediatrix sip endpoint ?
or
Cisco FXO --- FXS mediatrix sip endpoint ?
2.
Get the SIP trace from mediatrix see when it sends back 200OK
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 14-11-2012 12:34:55 PM
Hi Yaw,
Since this doesn't look like a TCL script issue, is it possible we can involve TAC to help us review the router configurations? We tried to open a case with TAC but they said since there's a script involved, we have to come to developer support first but the issue seems to be a router issue.
Thanks.
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 14-11-2012 02:14:11 PM
Hi Yaw,
The end point is Cisco FXO --- FXS mediatrix sip endpoin.
The sip log captured with the help of the telco on oct 25th is attached. The timing looks normal - 12 seconds to acceptance.
The log captured at a different time of the day from the mediatrix is also attached. The only thing i noticed from this log was that MakeCall request was received at 21:41:51 and about 21:41:54, we see these response. The interval is just about 4seconds which is when our TCL reports success. I don't know the meaning of these debug messages so I don't know if the two are related.
Oct 25 21:41:54 10.21.220.211 SipEngine [1BAE] Sending response to out of dialog OPTIONS.
Oct 25 21:41:54 10.21.221.62 CallManager [00A3] L9 C247076 ProgressingA.
Oct 25 21:41:54 10.21.221.62 CallManager [00A4] L9 C247076 InternalProgressingA - CallStatusA event sent | call status eSTATUS_PROGRESSING.
Oct 25 21:41:54 10.21.221.62 FxsInterface [00A5] L9 - Event CallStatus(5) on state "CONTROL WAITING RESPONSE"
Oct 25 21:41:54 10.21.221.62 FxsInterface [00A6] L9 - Change state from "CONTROL WAITING RESPONSE" to "CONTROL RING"
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 14-11-2012 04:09:51 PM
This is what I guessed too --> Cisco FXO --- FXS mediatrix sip endpoin
I wonder if we get "connected" because of FXS port, I wil check it out.
If posible just turn "deb vpm signal" on Cisco side see when we get.
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 15-11-2012 12:13:26 PM
This is the fact of FXS feature,
Cisco FXO --- FXS mediatrix sip endpoin.
When we connect to FXS we get "connect" immediately.
Created by: Chris Manuh on 01-11-2012 09:13:32 AM
I have a TCL script that uses 'leg setup' to make an outbound call. Once the call is connected it, plays a pre-recorded message to the caller and disconnects. The script works on our development environment. however, when we deployed the script on our client's network, we noticed that "leg setup" always returns ls_000 status at about 4seconds, and usually long before the phone actually starts ringing and before the caller actually picks up the call. So to the TCL script, since "leg setup" has already returned success, the script has started playing the message. so if the person picks up the call, they don't hear the beginning of the message. Any suggestions or ideas on how to address this is greatly appreciated.
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 01-11-2012 11:47:49 AM
It's hard to tell without seeing log, configuration and script, is it possible to attach them ? At least call setup part of script.
Thanks
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 07-11-2012 07:54:00 PM
Do you havelog for
deb voip app tcl
deb voip app scr
?
I don't think it's psoobile t rell what's going on by only seeing this log and two lines of script.
<h2>If you don't like to post you script here you can send it to [email protected]</h2>
Thanks !
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 07-11-2012 06:52:56 PM
Here's a log (Telephone number replaced with 9905977XXXX):
7148619: Nov 8 00:00:32.415:
7148620: Nov 8 00:00:32.415: //-1//TCL :EE44BB83A4000:/tcl_PutsObjCmd: action_http_request_complete - complete
7148621: Nov 8 00:00:32.415:
7148622: Nov 8 00:00:33.163: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_begin:
Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
Source Call Id=969250, Digit=6, DigitBeginFlags=0x0,
Rtp Timestamp=0x85061298, Rtp Expiration=0x0
7148623: Nov 8 00:00:33.163: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_end:
Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
Source Call Id=969250, Digit=6, Duration=100,
Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
7148624: Nov 8 00:00:33.163: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_end:
Call Entry(Handoff Depth=0)
7148625: Nov 8 00:00:33.351: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_begin:
Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
Source Call Id=969250, Digit=6, DigitBeginFlags=0x0,
Rtp Timestamp=0x85068F98, Rtp Expiration=0x0
7148626: Nov 8 00:00:33.351: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_end:
Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
Source Call Id=969250, Digit=6, Duration=100,
Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
7148627: Nov 8 00:00:33.351: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_end:
Call Entry(Handoff Depth=0)
7148628: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_begin:
Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
Source Call Id=969250, Digit=4, DigitBeginFlags=0x0,
Rtp Timestamp=0x85070C98, Rtp Expiration=0x0
7148629: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_end:
Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
Source Call Id=969250, Digit=4, Duration=100,
Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
7148630: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_api_call_digit_end:
Call Entry(Handoff Depth=0)
7148631: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCallReportDigits:
(callID=0xECA22, digit_event=0x0, enable=FALSE, consume=FALSE)
7148632: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCallReportDigits:
Enabled=TRUE, Call Id=969250
7148633: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_api_call_report_digits_done:
(vdbPtr=0x442EF460, callID=0xECA22, disp=0, digit_event=0x0, enable=FALSE, consume=FALSE)
7148634: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_api_call_report_digits_done:
Enabled=TRUE, Disposition=0x0, Interface=0x442EF460, Call Id=969250
7148635: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_api_call_report_digits_done:
Call Entry(Initial Digit Timeout=15000(ms), Inter Digit Timeout=10000(ms))
7148636: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCallProceeding:
Progress Indication=NULL(0)
7148637: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCallSetupRequest:
Destination=, Calling IE Present=TRUE, Mode=0,
Outgoing Dial-peer=10, Params=0x11EBA0F4, Progress Indication=ORIGINATING SIDE IS NON ISDN(3)
7148638: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_fill_tg_params:
Not a cic call
7148639: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCallSetupRequest:
Trunk Group Select Interface Success;
Interface=0x1535C108, Selected Interface=1, Selected DSL=-1
7148640: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCheckClipClir:
In: Calling Number=2000(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
7148641: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCheckClipClir:
Out: Calling Number=2000(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
7148642: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCallSetupRequest:
Destination Pattern=9[2-9]..[2-9]......$, Called Number=9905977XXXX, Digit Strip=TRUE
7148643: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccCallSetupRequest:
Calling Number=2000(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
Called Number=9905977XXXX(TON=Unknown, NPI=Unknown),
Redirect Number=, Display Info=Main Reception
Account Number=, Final Destination Flag=FALSE,
Guid=22F9126D-286E-11E2-BBF3-9037F7B46B81, Outgoing Dial-peer=10
7148644: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/cc_api_display_ie_subfields:
ccCallSetupRequest:
cisco-username=
----- ccCallInfo IE subfields -----
cisco-ani=2000
cisco-anitype=0
cisco-aniplan=0
cisco-anipi=0
cisco-anisi=0
dest=9905977XXXX
cisco-desttype=0
cisco-destplan=0
cisco-rdie=FFFFFFFF
cisco-rdn=
cisco-rdntype=0
cisco-rdnplan=0
cisco-rdnpi=0
cisco-rdnsi=0
cisco-redirectreason=0 fwd_final_type =0
final_redirectNumber =
hunt_group_timeout =0
7148645: Nov 8 00:00:33.683: //969250/22F9126DBBF3/CCAPI/ccIFCallSetupRequestPrivate:
Interface=0x1535C108, Interface Type=6, Destination=, Mode=0x0,
Call Params(Calling Number=2000,(Calling Name=Main Reception)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentati
on=Allowed),
Called Number=9905977XXXX(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
Subscriber Type Str=RegularLine, FinalDestinationFlag=FALSE, Outgoing Dial-peer=10, Call Count On=FALSE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=OUTBOUND, tg_label_flag=2, Application Call Id=)
7148646: Nov 8 00:00:33.683: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
7148647: Nov 8 00:00:33.683: :cc_get_feature_vsa malloc success
7148648: Nov 8 00:00:33.683: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
7148649: Nov 8 00:00:33.683: cc_get_feature_vsa count is 3
7148650: Nov 8 00:00:33.683: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
7148651: Nov 8 00:00:33.683: :FEATURE_VSA attributes are: feature_name:0,feature_time:328741704,feature_id:1948093
7148652: Nov 8 00:00:33.683: //969251/22F9126DBBF3/CCAPI/ccIFCallSetupRequestPrivate:
SPI Call Setup Request Is Success; Interface Type=6, FlowMode=1
7148653: Nov 8 00:00:33.687: //969250/22F9126DBBF3/CCAPI/ccCallSetupRequest:
Trunk Group Call Setting;
Call Entry(Retry Count=0, Voice Class Cause Code=0)
7148654: Nov 8 00:00:33.687: //969251/22F9126DBBF3/CCAPI/ccCallSetContext:
Context=0x11EBA0A4
7148655: Nov 8 00:00:33.687: //969250/22F9126DBBF3/CCAPI/ccSaveDialpeerTag:
Outgoing Dial-peer=10
7148656: Nov 8 00:00:33.687: //969250/22F9126DBBF3/CCAPI/cc_api_modify_tgt_cid_call_active_record:
Target Trkgrp Route Label=OUTBOUND, tg_label_flag=TRUE, Call Id=0xECA22
7148657: Nov 8 00:00:33.687: //969251/22F9126DBBF3/CCAPI/cc_api_call_proceeding:
Interface=0x1535C108, Progress Indication=NULL(0)
7148658: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/cc_api_call_cut_progress:
Interface=0x1535C108, Progress Indication=INBAND(8), Signal Indication=INTERCEPT(2),
Cause Value=0
7148659: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/cc_api_call_cut_progress:
Call Entry(Responsed=TRUE)
7148660: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/ccCallCutProgress:
Progress Indication=INBAND(8), Signal Indication=INTERCEPT(2), Cause Value=0
Voice Call Send Alert=FALSE, Call Entry(Alert Sent=FALSE)
7148661: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/ccCallCutProgress:
Call Entry(Responsed=TRUE)
7148662: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/ccGenerateToneInfo:
Stop Tone On Digit=FALSE, Tone=Null,
Tone Direction=Network, Params=0x0, Call Id=969250
7148663: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/ccConferenceCreate:
(confID=0x3A68104, callID1=0xECA22, gcid=22F9126D-286E11E2-BBF39037-F7B46B81, tag=0x0)
7148664: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/ccConferenceCreate:
(confID=0x3A68104, callID2=0xECA23, gcid=22F9126D-286E11E2-BBF39037-F7B46B81, tag=0x0)
7148665: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/ccConferenceCreate:
Conference Id=0x3A68104, Call Id1=969250, Call Id2=969251, Tag=0x0
7148666: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/cc_api_bridge_done:
Conference Id=0x5736D, Source Interface=0x442EF460, Source Call Id=969250,
Destination Call Id=969251, Disposition=0x0, Tag=0xFFFFFFFF
7148667: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/cc_api_bridge_done:
Conference Id=0x5736D, Source Interface=0x1535C108, Source Call Id=969251,
Destination Call Id=969250, Disposition=0x0, Tag=0xFFFFFFFF
7148668: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/cc_generic_bridge_done:
Conference Id=0x5736D, Source Interface=0x1535C108, Source Call Id=969251,
Destination Call Id=969250, Disposition=0x0, Tag=0xFFFFFFFF
7148669: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/ccConferenceCreate:
Call Entry(Conference Id=0x5736D, Destination Call Id=969251)
7148670: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/ccConferenceCreate:
Call Entry(Conference Id=0x5736D, Destination Call Id=969250)
7148671: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/cc_api_caps_ind:
Destination Interface=0x1535C108, Destination Call Id=969251, Source Call Id=969250,
Caps(Codec=0x1, Fax Rate=0x2, Vad=0x1,
Modem=0x2, Codec Bytes=160, Signal Type=2)
7148672: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/cc_api_caps_ind:
Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
Playout Max=1000(ms), Fax Nom=300(ms))
7148673: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/cc_api_caps_ind:
Destination Interface=0x442EF460, Destination Call Id=969250, Source Call Id=969251,
Caps(Codec=0x1, Fax Rate=0x1, Vad=0x1,
Modem=0x2, Codec Bytes=160, Signal Type=2)
7148674: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/cc_api_caps_ind:
Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
Playout Max=1000(ms), Fax Nom=300(ms))
7148675: Nov 8 00:00:37.315: //969251/22F9126DBBF3/CCAPI/cc_api_caps_ack:
Destination Interface=0x442EF460, Destination Call Id=969250, Source Call Id=969251,
Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Vad=OFF(0x1),
Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=3925)
7148676: Nov 8 00:00:37.315: //969250/22F9126DBBF3/CCAPI/cc_api_caps_ack:
Destination Interface=0x1535C108, Destination Call Id=969251, Source Call Id=969250,
Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_NONE(0x1), Vad=OFF(0x1),
Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=1712)
7148677: Nov 8 00:00:37.319: //969250/22F9126DBBF3/CCAPI/ccCallFeature:
Feature Type=25, Call Id=969250
7148678: Nov 8 00:00:37.319: //969250/22F9126DBBF3/CCAPI/cc_api_voice_mode_event:
Call Id=969250
7148679: Nov 8 00:00:37.319: //969250/22F9126DBBF3/CCAPI/cc_api_voice_mode_event:
Call Entry(Context=0x1200D228)
7148680: Nov 8 00:00:37.319: //969251/22F9126DBBF3/CCAPI/cc_api_voice_mode_event:
Call Id=969251
7148681: Nov 8 00:00:37.319: //969251/22F9126DBBF3/CCAPI/cc_api_voice_mode_event:
Call Entry(Context=0x11EBA0A4)
7148682: Nov 8 00:00:37.319: //969251/22F9126DBBF3/CCAPI/cc_api_call_connected:
Interface=0x1535C108, Data Bitmask=0x1, Progress Indication=DESTINATION IS NON ISDN(2),
Connection Handle=0
7148683: Nov 8 00:00:37.319: //969251/22F9126DBBF3/CCAPI/cc_api_call_connected:
Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)
7148684: Nov 8 00:00:37.319: //969250/22F9126DBBF3/CCAPI/cc_process_notify_bridge_done:
Conference Id=0x5736D, Call Id1=969250, Call Id2=969251
7148685: Nov 8 00:00:37.319: //969250/22F9126DBBF3/CCAPI/ccCallConnect:
Progress Indication=DESTINATION IS NON ISDN(2), Data Bitmask=0x1
7148686: Nov 8 00:00:37.319: //969250/22F9126DBBF3/CCAPI/ccCallConnect:
Call Entry(Connected=TRUE, Responsed=TRUE)
7148687: Nov 8 00:00:37.319: //969250/22F9126DBBF3/CCAPI/ccCallFeature:
Feature Type=25, Call Id=969250
7148688: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_api_call_disconnected:
Cause Value=16, Interface=0x442EF460, Call Id=969250
7148689: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_api_call_disconnected:
Call Entry(Responsed=TRUE, Cause Value=16, Retry Count=0)
7148690: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/ccConferenceDestroy:
Conference Id=0x5736D, Tag=0x0
7148691: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_api_bridge_drop_done:
Conference Id=0x5736D, Source Interface=0x442EF460, Source Call Id=969250,
Destination Call Id=969251, Disposition=0x0, Tag=0x0
7148692: Nov 8 00:01:04.975: //969251/22F9126DBBF3/CCAPI/cc_api_bridge_drop_done:
Conference Id=0x5736D, Source Interface=0x1535C108, Source Call Id=969251,
Destination Call Id=969250, Disposition=0x0, Tag=0x0
7148693: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_generic_bridge_done:
Conference Id=0x5736D, Source Interface=0x1535C108, Source Call Id=969251,
Destination Call Id=969250, Disposition=0x0, Tag=0x0
7148694: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/ccCallDisconnect:
Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=16)
7148695: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/ccCallDisconnect:
Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
7148696: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_api_get_transfer_info:
Transfer Number Is Null
7148697: Nov 8 00:01:04.975: //969251/22F9126DBBF3/CCAPI/ccCallDisconnect:
Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
7148698: Nov 8 00:01:04.975: //969251/22F9126DBBF3/CCAPI/ccCallDisconnect:
Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
7148699: Nov 8 00:01:04.975: //969251/22F9126DBBF3/CCAPI/cc_api_get_transfer_info:
Transfer Number Is Null
7148700: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_api_call_feature:
Feature Type=6, Interface=0x442EF460, Call Id=969250
7148701: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x442EF460, Tag=0x0, Call Id=969250,
Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
7148702: Nov 8 00:01:04.975: //969250/22F9126DBBF3/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
7148703: Nov 8 00:01:04.975: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
7148704: Nov 8 00:01:04.975: :cc_free_feature_vsa freeing 13983180
7148705: Nov 8 00:01:04.975: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
7148706: Nov 8 00:01:04.975: vsacount in free is 2
7148707: Nov 8 00:01:04.995: //969251/22F9126DBBF3/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x1535C108, Tag=0x0, Call Id=969251,
Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
7148708: Nov 8 00:01:04.995: //969251/22F9126DBBF3/CCAPI/cc_api_call_disconnect_done:
tg for this call is OUTBOUND success/fail is 1
7148709: Nov 8 00:01:04.995: //969251/22F9126DBBF3/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
7148710: Nov 8 00:01:04.995: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
7148711: Nov 8 00:01:04.995: :cc_free_feature_vsa freeing 13983340
7148712: Nov 8 00:01:04.995: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
7148713: Nov 8 00:01:04.995: vsacount in free is 1
----------------------------------
Leg setup looks as show below. the $phone number is initialized with a value before the call
set call_info(alertTime) 30
leg setup $phone call_info
----------------------------------
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 09-11-2012 12:23:15 AM
Hi Yaw,
Here's the log and a simplified script
Subject: RE: Leg setup command returns before call is connected
Replied by: Anusha Kannappan on 09-11-2012 04:42:07 AM
Hi Chris,
I had tried your sample app by replacing the vxml stuff with a normal media file since had issue TTS and it worked properly with the follwoing changes in FSM
set fsm(SETUP,ev_setup_indication) "action_setup same_state"
set fsm(any_state,ev_media_done) "action_voice_dialog_complete same_state"
Is it possible to check the same whether it is working fine for normal audio file first so that it would be easy to isolate the issue. Even if it is not working for normal audio file, please share the logs along with the IOS version being used in this case.
Thanks,
Anusha
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 09-11-2012 10:46:42 AM
Yes, the script does work but the issue is that the ios seems to accept the call, then establish another connection leg on its own and joins the two calls. from all the tests i've done, it happens always at a 4second mark from the time leg setup is issued to when it returns to my script with status ls_000. meanwhile, the actual call hasn't actually been answered yet so the script plays the message to dead air. if the message is long and the user picks up, they'll hear just the middle or end of the message.
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 09-11-2012 11:52:26 AM
ls_000 is a trigger event. I can think of two posibilties here.
1. far end is "connected"
2. IOS sned Tcl application false setup done event whick I think it's unlikely.
Two things we can try here
1. replace destination with a phone and let it ring forever see if there is setup done event sent.
2. debug underline protocol see if there is any "CONNECT", "200 OK" ... message sent from far end
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 09-11-2012 12:50:21 PM
The logs i posted was from last night. This is a log capture from the service provider (from october 25), when we thought the issue might be on their end. The connected status is reported after about 1minute, but our TCL script reported success at about 4 seconds. MakeCall request was made at Oct 25 21:41:51 and connected at Oct 25 21:42:08.
------------------------------
<!--[if gte mso 9]><xml>
<w:WordDocument>
<w
iew>Normal</wiew><w:Zoom>0</w:Zoom>
<w:TrackMoves />
<w:TrackFormatting />
<w
unctuationKerning /><w
alidateAgainstSchemas /><w:SaveIfXMLInvalid>false</w:SaveIfXMLInvalid>
<w:IgnoreMixedContent>false</w:IgnoreMixedContent>
<w:AlwaysShowPlaceholderText>false</w:AlwaysShowPlaceholderText>
<w
oNotPromoteQF /><w:LidThemeOther>EN-US</w:LidThemeOther>
<w:LidThemeAsian>X-NONE</w:LidThemeAsian>
<w:LidThemeComplexScript>X-NONE</w:LidThemeComplexScript>
<w:Compatibility>
<w:BreakWrappedTables />
<w:SnapToGridInCell />
<w:WrapTextWithPunct />
<w:UseAsianBreakRules />
<w
ontGrowAutofit /><w:SplitPgBreakAndParaMark />
<w:EnableOpenTypeKerning />
<w
ontFlipMirrorIndents /><w
verrideTableStyleHps /></w:Compatibility>
<w:BrowserLevel>MicrosoftInternetExplorer4</w:BrowserLevel>
<m:mathPr>
<m:mathFont m:val="Cambria Math" />
<m:brkBin m:val="before" />
<m:brkBinSub m:val="--" />
<m:smallFrac m:val="off" />
<m:dispDef />
<m:lMargin m:val="0" />
<m:rMargin m:val="0" />
<m:defJc m:val="centerGroup" />
<m:wrapIndent m:val="1440" />
<m:intLim m:val="subSup" />
<m:naryLim m:val="undOvr" />
</m:mathPr></w:WordDocument>
</xml><!-->
<!--[if gte mso 9]><xml>
<w:LatentStyles DefLockedState="false" DefUnhideWhenUsed="true"
DefSemiHidden="true" DefQFormat="false" DefPriority="99"
LatentStyleCount="267">
<w:LsdException Locked="false" Priority="0" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Normal" />
<w:LsdException Locked="false" Priority="9" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="heading 1" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 2" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 3" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 4" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 5" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 6" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 7" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 8" />
<w:LsdException Locked="false" Priority="9" QFormat="true" Name="heading 9" />
<w:LsdException Locked="false" Priority="39" Name="toc 1" />
<w:LsdException Locked="false" Priority="39" Name="toc 2" />
<w:LsdException Locked="false" Priority="39" Name="toc 3" />
<w:LsdException Locked="false" Priority="39" Name="toc 4" />
<w:LsdException Locked="false" Priority="39" Name="toc 5" />
<w:LsdException Locked="false" Priority="39" Name="toc 6" />
<w:LsdException Locked="false" Priority="39" Name="toc 7" />
<w:LsdException Locked="false" Priority="39" Name="toc 8" />
<w:LsdException Locked="false" Priority="39" Name="toc 9" />
<w:LsdException Locked="false" Priority="35" QFormat="true" Name="caption" />
<w:LsdException Locked="false" Priority="10" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Title" />
<w:LsdException Locked="false" Priority="1" Name="Default Paragraph Font" />
<w:LsdException Locked="false" Priority="11" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Subtitle" />
<w:LsdException Locked="false" Priority="22" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Strong" />
<w:LsdException Locked="false" Priority="20" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Emphasis" />
<w:LsdException Locked="false" Priority="59" SemiHidden="false"
UnhideWhenUsed="false" Name="Table Grid" />
<w:LsdException Locked="false" UnhideWhenUsed="false" Name="Placeholder Text" />
<w:LsdException Locked="false" Priority="1" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="No Spacing" />
<w:LsdException Locked="false" Priority="60" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Shading" />
<w:LsdException Locked="false" Priority="61" SemiHidden="false"
UnhideWhenUsed="false" Name="Light List" />
<w:LsdException Locked="false" Priority="62" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Grid" />
<w:LsdException Locked="false" Priority="63" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 1" />
<w:LsdException Locked="false" Priority="64" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 2" />
<w:LsdException Locked="false" Priority="65" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 1" />
<w:LsdException Locked="false" Priority="66" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 2" />
<w:LsdException Locked="false" Priority="67" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 1" />
<w:LsdException Locked="false" Priority="68" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 2" />
<w:LsdException Locked="false" Priority="69" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 3" />
<w:LsdException Locked="false" Priority="70" SemiHidden="false"
UnhideWhenUsed="false" Name="Dark List" />
<w:LsdException Locked="false" Priority="71" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Shading" />
<w:LsdException Locked="false" Priority="72" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful List" />
<w:LsdException Locked="false" Priority="73" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Grid" />
<w:LsdException Locked="false" Priority="60" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Shading Accent 1" />
<w:LsdException Locked="false" Priority="61" SemiHidden="false"
UnhideWhenUsed="false" Name="Light List Accent 1" />
<w:LsdException Locked="false" Priority="62" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Grid Accent 1" />
<w:LsdException Locked="false" Priority="63" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 1 Accent 1" />
<w:LsdException Locked="false" Priority="64" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 2 Accent 1" />
<w:LsdException Locked="false" Priority="65" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 1 Accent 1" />
<w:LsdException Locked="false" UnhideWhenUsed="false" Name="Revision" />
<w:LsdException Locked="false" Priority="34" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="List Paragraph" />
<w:LsdException Locked="false" Priority="29" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Quote" />
<w:LsdException Locked="false" Priority="30" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Intense Quote" />
<w:LsdException Locked="false" Priority="66" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 2 Accent 1" />
<w:LsdException Locked="false" Priority="67" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 1 Accent 1" />
<w:LsdException Locked="false" Priority="68" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 2 Accent 1" />
<w:LsdException Locked="false" Priority="69" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 3 Accent 1" />
<w:LsdException Locked="false" Priority="70" SemiHidden="false"
UnhideWhenUsed="false" Name="Dark List Accent 1" />
<w:LsdException Locked="false" Priority="71" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Shading Accent 1" />
<w:LsdException Locked="false" Priority="72" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful List Accent 1" />
<w:LsdException Locked="false" Priority="73" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Grid Accent 1" />
<w:LsdException Locked="false" Priority="60" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Shading Accent 2" />
<w:LsdException Locked="false" Priority="61" SemiHidden="false"
UnhideWhenUsed="false" Name="Light List Accent 2" />
<w:LsdException Locked="false" Priority="62" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Grid Accent 2" />
<w:LsdException Locked="false" Priority="63" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 1 Accent 2" />
<w:LsdException Locked="false" Priority="64" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 2 Accent 2" />
<w:LsdException Locked="false" Priority="65" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 1 Accent 2" />
<w:LsdException Locked="false" Priority="66" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 2 Accent 2" />
<w:LsdException Locked="false" Priority="67" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 1 Accent 2" />
<w:LsdException Locked="false" Priority="68" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 2 Accent 2" />
<w:LsdException Locked="false" Priority="69" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 3 Accent 2" />
<w:LsdException Locked="false" Priority="70" SemiHidden="false"
UnhideWhenUsed="false" Name="Dark List Accent 2" />
<w:LsdException Locked="false" Priority="71" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Shading Accent 2" />
<w:LsdException Locked="false" Priority="72" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful List Accent 2" />
<w:LsdException Locked="false" Priority="73" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Grid Accent 2" />
<w:LsdException Locked="false" Priority="60" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Shading Accent 3" />
<w:LsdException Locked="false" Priority="61" SemiHidden="false"
UnhideWhenUsed="false" Name="Light List Accent 3" />
<w:LsdException Locked="false" Priority="62" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Grid Accent 3" />
<w:LsdException Locked="false" Priority="63" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 1 Accent 3" />
<w:LsdException Locked="false" Priority="64" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 2 Accent 3" />
<w:LsdException Locked="false" Priority="65" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 1 Accent 3" />
<w:LsdException Locked="false" Priority="66" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 2 Accent 3" />
<w:LsdException Locked="false" Priority="67" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 1 Accent 3" />
<w:LsdException Locked="false" Priority="68" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 2 Accent 3" />
<w:LsdException Locked="false" Priority="69" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 3 Accent 3" />
<w:LsdException Locked="false" Priority="70" SemiHidden="false"
UnhideWhenUsed="false" Name="Dark List Accent 3" />
<w:LsdException Locked="false" Priority="71" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Shading Accent 3" />
<w:LsdException Locked="false" Priority="72" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful List Accent 3" />
<w:LsdException Locked="false" Priority="73" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Grid Accent 3" />
<w:LsdException Locked="false" Priority="60" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Shading Accent 4" />
<w:LsdException Locked="false" Priority="61" SemiHidden="false"
UnhideWhenUsed="false" Name="Light List Accent 4" />
<w:LsdException Locked="false" Priority="62" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Grid Accent 4" />
<w:LsdException Locked="false" Priority="63" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 1 Accent 4" />
<w:LsdException Locked="false" Priority="64" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 2 Accent 4" />
<w:LsdException Locked="false" Priority="65" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 1 Accent 4" />
<w:LsdException Locked="false" Priority="66" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 2 Accent 4" />
<w:LsdException Locked="false" Priority="67" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 1 Accent 4" />
<w:LsdException Locked="false" Priority="68" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 2 Accent 4" />
<w:LsdException Locked="false" Priority="69" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 3 Accent 4" />
<w:LsdException Locked="false" Priority="70" SemiHidden="false"
UnhideWhenUsed="false" Name="Dark List Accent 4" />
<w:LsdException Locked="false" Priority="71" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Shading Accent 4" />
<w:LsdException Locked="false" Priority="72" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful List Accent 4" />
<w:LsdException Locked="false" Priority="73" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Grid Accent 4" />
<w:LsdException Locked="false" Priority="60" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Shading Accent 5" />
<w:LsdException Locked="false" Priority="61" SemiHidden="false"
UnhideWhenUsed="false" Name="Light List Accent 5" />
<w:LsdException Locked="false" Priority="62" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Grid Accent 5" />
<w:LsdException Locked="false" Priority="63" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 1 Accent 5" />
<w:LsdException Locked="false" Priority="64" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 2 Accent 5" />
<w:LsdException Locked="false" Priority="65" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 1 Accent 5" />
<w:LsdException Locked="false" Priority="66" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 2 Accent 5" />
<w:LsdException Locked="false" Priority="67" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 1 Accent 5" />
<w:LsdException Locked="false" Priority="68" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 2 Accent 5" />
<w:LsdException Locked="false" Priority="69" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 3 Accent 5" />
<w:LsdException Locked="false" Priority="70" SemiHidden="false"
UnhideWhenUsed="false" Name="Dark List Accent 5" />
<w:LsdException Locked="false" Priority="71" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Shading Accent 5" />
<w:LsdException Locked="false" Priority="72" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful List Accent 5" />
<w:LsdException Locked="false" Priority="73" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Grid Accent 5" />
<w:LsdException Locked="false" Priority="60" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Shading Accent 6" />
<w:LsdException Locked="false" Priority="61" SemiHidden="false"
UnhideWhenUsed="false" Name="Light List Accent 6" />
<w:LsdException Locked="false" Priority="62" SemiHidden="false"
UnhideWhenUsed="false" Name="Light Grid Accent 6" />
<w:LsdException Locked="false" Priority="63" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 1 Accent 6" />
<w:LsdException Locked="false" Priority="64" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Shading 2 Accent 6" />
<w:LsdException Locked="false" Priority="65" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 1 Accent 6" />
<w:LsdException Locked="false" Priority="66" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium List 2 Accent 6" />
<w:LsdException Locked="false" Priority="67" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 1 Accent 6" />
<w:LsdException Locked="false" Priority="68" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 2 Accent 6" />
<w:LsdException Locked="false" Priority="69" SemiHidden="false"
UnhideWhenUsed="false" Name="Medium Grid 3 Accent 6" />
<w:LsdException Locked="false" Priority="70" SemiHidden="false"
UnhideWhenUsed="false" Name="Dark List Accent 6" />
<w:LsdException Locked="false" Priority="71" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Shading Accent 6" />
<w:LsdException Locked="false" Priority="72" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful List Accent 6" />
<w:LsdException Locked="false" Priority="73" SemiHidden="false"
UnhideWhenUsed="false" Name="Colorful Grid Accent 6" />
<w:LsdException Locked="false" Priority="19" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Subtle Emphasis" />
<w:LsdException Locked="false" Priority="21" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Intense Emphasis" />
<w:LsdException Locked="false" Priority="31" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Subtle Reference" />
<w:LsdException Locked="false" Priority="32" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Intense Reference" />
<w:LsdException Locked="false" Priority="33" SemiHidden="false"
UnhideWhenUsed="false" QFormat="true" Name="Book Title" />
<w:LsdException Locked="false" Priority="37" Name="Bibliography" />
<w:LsdException Locked="false" Priority="39" QFormat="true" Name="TOC Heading" />
</w:LatentStyles>
</xml><!--><!--[if gte mso 10]>
<mce:style><!
/* Style Definitions */
table.MsoNormalTable
{mso-style-name:"Table Normal";
mso-tstyle-rowband-size:0;
mso-tstyle-colband-size:0;
mso-style-noshow:yes;
mso-style-priority:99;
mso-style-parent:"";
mso-padding-alt:0cm 5.4pt 0cm 5.4pt;
mso-para-margin:0cm;
mso-para-margin-bottom:.0001pt;
mso-pagination:widow-orphan;
font-size:10.0pt;
font-family:"Times New Roman","serif";}
-->
<!-- -->
Oct 25 21:41:48 10.21.221.62 CommandDigitInterface [001D] L9 - Event Reset(Tone=eNORMAL, bAcceptCallWaitingPossible=0, bSwitchCallsPossible=0, bEndActiveCallPossibl
e=0, bConferencePossible=0, bCallTransferPossible=0) on state "FINAL"
Oct 25 21:41:48 10.21.221.62 CommandDigitInterface [001E] L9 - Event Reset was not handled by state "FINAL", send the event to his parent "ROOT"
Oct 25 21:41:48 10.21.221.62 CommandDigitInterface [001F] L9 - Change state from "FINAL" to "INITIAL"
Oct 25 21:41:48 10.21.221.62 CommandDigitInterface [0020] L9 - Change state from "INITIAL" to "IDLE"
Oct 25 21:41:48 10.21.221.62 FxsInterface [0021] L9 - Change state from "CONTROL WAIT PERMISSION" to "CONTROL MODE"
Oct 25 21:41:48 10.21.221.62 AnalogEndpoint [0022] OffHookDetected change mode to Call Setup on EP9
Oct 25 21:41:48 10.21.221.62 AnalogLine [0023] iPlayToneA - Tone 0, Endpoint 9
Oct 25 21:41:48 10.21.221.62 AnalogEndpoint [0024] LowPlayTone EP9, DIALTONE, Tone Country: NorthAmerica1 Tone, tone info 0x2
Oct 25 21:41:48 10.21.221.62 AnalogLine [0025] Hapiecan_state DSP1, op1:0x3 op2:0x1c80
Oct 25 21:41:48 10.21.221.62 PotsEndpoint [0026] EP 9 HHEvent - NetVHD mode change event op1:2 op2:0 Call Setup.
Oct 25 21:41:49 10.21.221.62 PotsEndpoint [0027] EP 9 HHEvent - Dialed digit detected 1.
Oct 25 21:41:49 10.21.221.62 FxsInterface [0028] L9 - Event DtmfDetect(1) on state "CONTROL MODE"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [0029] L9 - Event Dtmf(1) on state "IDLE"
Oct 25 21:41:49 10.21.221.62 AnalogLine [002A] iStopToneA - Endpoint 9
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [002B] L9 - Change state from "IDLE" to "DTMF"
Oct 25 21:41:49 10.21.221.62 PotsEndpoint [002C] EP 9 HHEvent - DTMF Off 1.
Oct 25 21:41:49 10.21.221.62 FxsInterface [002D] L9 - Event DtmfTerminated(1) on state "CONTROL MODE"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [002E] L9 - Event DtmfOff(1) on state "DTMF"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [002F] L9 - Event DtmfOff(1) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [0030] L9 - Event DtmfOff(1) was not handled
Oct 25 21:41:49 10.21.221.62 PotsEndpoint [0031] EP 9 HHEvent - Dialed digit detected 9.
Oct 25 21:41:49 10.21.221.62 FxsInterface [0032] L9 - Event DtmfDetect(9) on state "CONTROL MODE"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [0033] L9 - Event Dtmf(9) on state "DTMF"
Oct 25 21:41:49 10.21.221.62 PotsEndpoint [0034] EP 9 HHEvent - DTMF Off 9.
Oct 25 21:41:49 10.21.221.62 FxsInterface [0035] L9 - Event DtmfTerminated(9) on state "CONTROL MODE"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [0036] L9 - Event DtmfOff(9) on state "DTMF"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [0037] L9 - Event DtmfOff(9) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [0038] L9 - Event DtmfOff(9) was not handled
Oct 25 21:41:49 10.21.221.62 PotsEndpoint [0039] EP 9 HHEvent - Dialed digit detected 0.
Oct 25 21:41:49 10.21.221.62 FxsInterface [003A] L9 - Event DtmfDetect(0) on state "CONTROL MODE"
Oct 25 21:41:49 10.21.221.62 CommandDigitInterface [003B] L9 - Event Dtmf(0) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [003C] EP 9 HHEvent - DTMF Off 0.
Oct 25 21:41:50 10.21.221.62 FxsInterface [003D] L9 - Event DtmfTerminated(0) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [003E] L9 - Event DtmfOff(0) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [003F] L9 - Event DtmfOff(0) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0040] L9 - Event DtmfOff(0) was not handled
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [0041] EP 9 HHEvent - Dialed digit detected 5.
Oct 25 21:41:50 10.21.221.62 FxsInterface [0042] L9 - Event DtmfDetect(5) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0043] L9 - Event Dtmf(5) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [0044] EP 9 HHEvent - DTMF Off 5.
Oct 25 21:41:50 10.21.221.62 FxsInterface [0045] L9 - Event DtmfTerminated(5) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0046] L9 - Event DtmfOff(5) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0047] L9 - Event DtmfOff(5) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0048] L9 - Event DtmfOff(5) was not handled
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [0049] EP 9 HHEvent - Dialed digit detected 9.
Oct 25 21:41:50 10.21.221.62 FxsInterface [004A] L9 - Event DtmfDetect(9) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [004B] L9 - Event Dtmf(9) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [004C] EP 9 HHEvent - DTMF Off 9.
Oct 25 21:41:50 10.21.221.62 FxsInterface [004D] L9 - Event DtmfTerminated(9) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [004E] L9 - Event DtmfOff(9) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [004F] L9 - Event DtmfOff(9) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0050] L9 - Event DtmfOff(9) was not handled
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [0051] EP 9 HHEvent - Dialed digit detected 4.
Oct 25 21:41:50 10.21.221.62 FxsInterface [0052] L9 - Event DtmfDetect(4) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0053] L9 - Event Dtmf(4) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [0054] EP 9 HHEvent - DTMF Off 4.
Oct 25 21:41:50 10.21.221.62 FxsInterface [0055] L9 - Event DtmfTerminated(4) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0056] L9 - Event DtmfOff(4) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0057] L9 - Event DtmfOff(4) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0058] L9 - Event DtmfOff(4) was not handled
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [0059] EP 9 HHEvent - Dialed digit detected 9.
Oct 25 21:41:50 10.21.221.62 FxsInterface [005A] L9 - Event DtmfDetect(9) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [005B] L9 - Event Dtmf(9) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [005C] EP 9 HHEvent - DTMF Off 9.
Oct 25 21:41:50 10.21.221.62 FxsInterface [005D] L9 - Event DtmfTerminated(9) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [005E] L9 - Event DtmfOff(9) on state "DTMF"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [005F] L9 - Event DtmfOff(9) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0060] L9 - Event DtmfOff(9) was not handled
Oct 25 21:41:50 10.21.221.62 PotsEndpoint [0061] EP 9 HHEvent - Dialed digit detected 0.
Oct 25 21:41:50 10.21.221.62 FxsInterface [0062] L9 - Event DtmfDetect(0) on state "CONTROL MODE"
Oct 25 21:41:50 10.21.221.62 CommandDigitInterface [0063] L9 - Event Dtmf(0) on state "DTMF"
Oct 25 21:41:51 10.21.221.62 PotsEndpoint [0064] EP 9 HHEvent - DTMF Off 0.
Oct 25 21:41:51 10.21.221.62 FxsInterface [0065] L9 - Event DtmfTerminated(0) on state "CONTROL MODE"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0066] L9 - Event DtmfOff(0) on state "DTMF"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0067] L9 - Event DtmfOff(0) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0068] L9 - Event DtmfOff(0) was not handled
Oct 25 21:41:51 10.21.221.62 PotsEndpoint [0069] EP 9 HHEvent - Dialed digit detected 1.
Oct 25 21:41:51 10.21.221.62 FxsInterface [006A] L9 - Event DtmfDetect(1) on state "CONTROL MODE"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [006B] L9 - Event Dtmf(1) on state "DTMF"
Oct 25 21:41:51 10.21.221.62 PotsEndpoint [006C] EP 9 HHEvent - DTMF Off 1.
Oct 25 21:41:51 10.21.221.62 FxsInterface [006D] L9 - Event DtmfTerminated(1) on state "CONTROL MODE"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [006E] L9 - Event DtmfOff(1) on state "DTMF"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [006F] L9 - Event DtmfOff(1) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0070] L9 - Event DtmfOff(1) was not handled
Oct 25 21:41:51 10.21.221.62 PotsEndpoint [0071] EP 9 HHEvent - Dialed digit detected 3.
Oct 25 21:41:51 10.21.221.62 FxsInterface [0072] L9 - Event DtmfDetect(3) on state "CONTROL MODE"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0073] L9 - Event Dtmf(3) on state "DTMF"
Oct 25 21:41:51 10.21.221.62 PotsEndpoint [0074] EP 9 HHEvent - DTMF Off 3.
Oct 25 21:41:51 10.21.221.62 FxsInterface [0075] L9 - Event DtmfTerminated(3) on state "CONTROL MODE"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0076] L9 - Event DtmfOff(3) on state "DTMF"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0077] L9 - Event DtmfOff(3) was not handled by state "DTMF", send the event to his parent "ROOT"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0078] L9 - Event DtmfOff(3) was not handled
Oct 25 21:41:51 10.21.221.62 PotsEndpoint [0079] EP 9 HHEvent - Dialed digit detected 9.
Oct 25 21:41:51 10.21.221.62 FxsInterface [007A] L9 - Event DtmfDetect(9) on state "CONTROL MODE"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [007B] L9 - Event Dtmf(9) on state "DTMF"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [007C] L9 - Change state from "DTMF" to "FINAL"
190594901301:51 10.21.221.62 FxsInterface [007D] L9 - Event MakeCall(
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [007E] L9 - Event Terminate() on state "FINAL"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [007F] L9 - Event Terminate was not handled by state "FINAL", send the event to his parent "ROOT"
Oct 25 21:41:51 10.21.221.62 CommandDigitInterface [0080] L9 - Change state from "FINAL" to "FINAL"
Oct 25 21:41:51 10.21.221.62 FxsInterface [0081] L9 - Change state from "CONTROL MODE" to "CONTROL WAITING RESPONSE"
Oct 25 21:41:51 10.21.221.62 CallManager [0082] L9 UI9 MakeCallA - source #SIP#sme2.mtncbl.net,0,HAM14-NHCH-9055231184-01,| | destination #TEL#19059490130|.
Oct 25 21:41:51 10.21.221.62 CallManager [0083] InternalMakeCallA - ILineApprovalManager::ApproveLineToProtocolCall returned eLINE_APPROVED.
Oct 25 21:41:51 10.21.221.62 CallManager [0084] L9 UI9 CCallTable::AddCall | ACTIVE 1: 247076.
Oct 25 21:41:51 10.21.221.62 CallManager [0085] L9 C247076 InternalMakeCallA - InviteA event sent | source #SIP#sme2.mtncbl.net,0,HAM14-NHCH-9055231184-01,| | destination #TEL#19059490130|.
Oct 25 21:41:51 10.21.221.62 CallManager [0086] L9 InternalMakeCallA - CallUpdatedA event sent.
Oct 25 21:41:51 10.21.221.62 CallManager [0087] L9 UI9 ReleaseControlA.
Oct 25 21:41:51 10.21.221.62 FxsInterface [0088] L9 - Event CallUpdated(3075EEB8) on state "CONTROL WAITING RESPONSE"
Oct 25 21:41:51 10.21.221.62 SipEngine [0089] CCallCxMgr::Invite L9 C247076
Oct 25 21:41:51 10.21.221.62 SipEngine [008A] CCallCxMgr::Create L9 C247076
Oct 25 21:41:51 10.21.221.62 CRtpEngine [008B] CRtpConnection::SelectSessionMode() - Success - mode = 0, - AID9, CID247076
Oct 25 21:41:51 10.21.221.62 CRtpEngine [008C] CRtpPacketizer::ModifySettings() - encoding = PCMU, payload size = 160, SID size = 0, TS inc. = 15
Oct 25 21:41:51 10.21.221.62 CRtpEngine [008D] CRtpConnection::SelectCompressionAlgorithm() - Success - payload = PCMU ptime = 20, - AID9, CID247076
Oct 25 21:41:51 10.21.221.62 CRtpEngine [008E] CRtcpSession:
pen() - EnterOct 25 21:41:51 10.21.221.62 CRtpEngine [008F] CUdpSocket::Create() - Success
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0090] CUdpSocket::Bind() - Success - 0.0.0.0:5005
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0091] CRtcpSession:
pen() - ExitOct 25 21:41:51 10.21.221.62 CRtpEngine [0092] CRtpSession:
pen() - Enter - AID9, SID247076Oct 25 21:41:51 10.21.221.62 CRtpEngine [0093] CUdpSocket::Create() - Success
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0094] CUdpSocket::Bind() - Success - 0.0.0.0:5004
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0095] CUdpSocket::Connect() - Success - 0.0.0.0:0
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0096] CUdpSocket::SetAllowAnySource() - Success
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0097] CUdpSocket::SetUdpChecksum() - Success
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0098] CUdpSocket::SetTos() - Success - Tos= 184
Oct 25 21:41:51 10.21.221.62 CRtpEngine [0099] CUdpSocket::Set8021QUserPriority() - Success - Priority= 255
Oct 25 21:41:51 10.21.221.62 CRtpEngine [009A] CRtpSession:
pen() - Success - AID9, SID247076Oct 25 21:41:51 10.21.221.62 CRtpEngine [009B] CRtpConnection:
pen() - Success - AID9, CID247076Oct 25 21:41:51 10.21.221.62 CRtpEngine [009C] CRtpEngine:
penConnection() - Success - AID9, CID247076Oct 25 21:41:51 10.21.221.62 SipEngine [009D] L9 C247076 sending invite.
Oct 25 21:41:51 10.21.221.62 PotsEndpoint [009E] EP 9 HHEvent - DTMF Off 9.
Oct 25 21:41:51 10.21.221.62 FxsInterface [009F] L9 - Event DtmfTerminated(9) on state "CONTROL WAITING RESPONSE"
Oct 25 21:41:51 10.21.221.62 FxsInterface [00A0] L9 - Event DtmfTerminated was not handled by state "CONTROL WAITING RESPONSE", send the event to his parent "CONTROL COMPLEX"
Oct 25 21:41:51 10.21.221.62 FxsInterface [00A1] L9 - Event DtmfTerminated was not handled by state "CONTROL COMPLEX", send the event to his parent "ROOT"
Oct 25 21:41:51 10.21.221.62 FxsInterface [00A2] L9 - Event DtmfTerminated was not handled
Oct 25 21:41:54 10.21.220.211 SipEngine [1BAE] Sending response to out of dialog OPTIONS.
Oct 25 21:41:54 10.21.221.62 CallManager [00A3] L9 C247076 ProgressingA.
Oct 25 21:41:54 10.21.221.62 CallManager [00A4] L9 C247076 InternalProgressingA - CallStatusA event sent | call status eSTATUS_PROGRESSING.
Oct 25 21:41:54 10.21.221.62 FxsInterface [00A5] L9 - Event CallStatus(5) on state "CONTROL WAITING RESPONSE"
Oct 25 21:41:54 10.21.221.62 FxsInterface [00A6] L9 - Change state from "CONTROL WAITING RESPONSE" to "CONTROL RING"
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00A7] CRtpEngine::SetDynamicPayloadType() -EEncodingName 1, -PayloadType 96, - AID 9, CID 247076, - mode 2 SUCCESS
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00A8] CRtpSession::Modify() - Success - mode: 3 - realmode: 3 - AID9, SID247076
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00A9] CRtpConnection::SelectSessionMode() - Success - mode = 3, - AID9, CID247076
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00AA] CRtpPacketizer::ModifySettings() - encoding = PCMU, payload size = 160, SID size = 0, TS inc. = 15
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00AB] CUdpSocket::SetTos() - Success - Tos= 184
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00AC] CUdpSocket::Set8021QUserPriority() - Success - Priority= 255
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00AD] CRtpSession::Modify() - (Outgoing codec) - Success - payload: PCMU, ptime: 20 - AID9, SID247076
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00AE] CRtpConnection::SelectCompressionAlgorithm() - Success - payload = PCMU ptime = 20, - AID9, CID247076
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00AF] CRtpConnection::Modify() - (Connection) Success - AID9, CID247076
Oct 25 21:41:54 10.21.221.62 CRtpEngine [00B0] CRtpEngine::ModifyConnection() - Success - AID9, CID247076
Oct 25 21:41:54 10.21.221.62 AnalogEndpoint [00B1] ReceivePacket - Endpoint 9 : Packet with wrong connection Id=247076 (can be normal if switching call - m_unCallId is 0).
Oct 25 21:41:54 10.21.221.62 AnalogLine [00B2] iStartVoiceCommunicationA- Endpoint 9, Algo 96 (0 if not specified)
Oct 25 21:41:54 10.21.221.62 AnalogEndpoint [00B3] EP9 SetRuntimeOptions (old-new) (T38=0-0, CCCodec=0x60-0x60, MCEDin=0-0,MCEDout=0-0, IgnCNG=0-0, IgnCED=0-0, CDIS=1-1, AleIgnCNG=0-0,AleIngCED=0-0)valid=1, (DtmfInBd=0-0)valid=1 (FlashRtpTx=1-1)valid=1 (FlashRtpRx=1-1)valid=1
Oct 25 21:41:54 10.21.221.62 AnalogEndpoint [00B4] GoInVoiceMode change mode to Packet Voice on EP9
Oct 25 21:41:54 10.21.221.62 AnalogLine [00B5] Hapiecan_state DSP1, op1:0x3 op2:0x1c80
Oct 25 21:41:54 10.21.221.62 PotsEndpoint [00B6] EP 9 HHEvent - NetVHD mode change event op1:3 op2:0 Packet Voice.
Oct 25 21:41:54 10.21.221.62 AnalogEndpoint [00B7] EP 9 Voice encoder rate change to 0x40a0
Oct 25 21:41:54 10.21.221.62 AnalogEndpoint [00B8] G.711 mu-law 64 kbps generic VAD
Oct 25 21:41:54 10.21.221.62 AnalogEndpoint [00B9] EP 9 Voice encoder rate change to 0x60
Oct 25 21:41:54 10.21.221.62 AnalogEndpoint [00BA] G.711 mu-law 64 kbps
Oct 25 21:42:08 10.21.221.62 25 21:42:5 10.21.221.62 CallManager [00BB] L9 C247076 AcceptedA.
Oct 25 21:42:08 10.21.221.62 25 21:42:5 10.21.221.62 CallManager [00BC] L9 C247076 InternalAcceptedA - ActivateMediaA event sent.
Oct 25 21:42:08 10.21.221.62 25 21:42:5 10.21.221.62 CallManager [00BD] L9 C247076 InternalAcceptedA - CallStatusA event sent | call status eSTATUS_CONNECTED.
Oct 25 21:42:08 10.21.221.62 25 21:42:5 10.21.221.62 FxsInterface [00BE] L9 - Event CallStatus(6) on state "CONTROL RING"
Oct 25 21:42:08 10.21.221.62 25 21:42:5 10.21.221.62 FxsInterface [00BF] L9 - Change state from "CONTROL RING" to "IN PROGRESS"
Oct 25 21:42:08 10.21.221.62 25 21:42:5 10.21.221.62 SipEngine [00C0] L9 C247076 session established.
Oct 25 21:42:08 10.21.221.62 25 21:42:5 10.21.221.62 SipEngine [00C1] CCallCxMgr::ActivateMedia L9 C247076
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 09-11-2012 01:02:56 PM
This is interesting/
What is the protocl ? Can we capture debug from GW ?
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 09-11-2012 03:04:40 PM
Are you referring to the voice gateway that the TCL is running from? if so then yes. we can capture debug logs. any specific debug you want to see?
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 09-11-2012 05:08:39 PM
I don't know what protocol is used between GW and destination. Please run the debug for that protocol plus
deb voip app tcl
deb voip app scr
deb voip ccapi inout
thanks
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 12-11-2012 09:50:05 PM
Hi Yaw,
Here's the log capture (Attached) of the script previously posted with the debugs turned on.
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 12-11-2012 10:35:35 PM
Do you know you client environment well ? what is on the other end ?
Is h323 trunk ? Is it possible to capture Wireshark log ?
Another thing to try is that try to add a phone call trigger (calling from phone to trigger script, ev_setup_indication). This may tell something
In really life do you really manulay start script ?
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 13-11-2012 01:41:53 PM
from what I've been told, the Cisco IOS router connects to a mediatrix sip endpoint with analog lines. The mediatrix connects to a softswitch at the telco side and the mediatrix and the softswitch talk sip but it's beyond my control.
The test i run was triggered manually from the console. in production, it'll be triggered from a timer via event manager. the app is an outbound dialer that calls 100s of people and deliver custom messages.
We interact with their gateway remotely so I don't think we'll be able to wireshark it.
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 13-11-2012 02:25:03 PM
Hi Yaw,
After checking with one of our cisco engineers, he says it may be possible to do wireshark remotely. Is there any thing in particular you want to capture?
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 13-11-2012 02:31:08 PM
mediatrix sip endpoint with analog lines
If it's analog, Wireshark is out of option. Is FXO or FXS ?
Cisco FXS---- FXO mediatrix sip endpoint ?
or
Cisco FXO --- FXS mediatrix sip endpoint ?
If it's SIP trunk we just need to turn
deb ccsip mess
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 14-11-2012 12:54:52 PM
TAC is right if there is a Tcl involved. They don't support.
But if it's not Tcl issue it could be far end, TAC cannot help much either.Just like Cisco Tcl IVR application, far end can connect call as soon as cll arrived.
Also we are not only deal with single componet,we don't know how they handle the incoming call.
" Cisco IOS router connects to a mediatrix sip endpoint with analog
lines. The mediatrix connects to a softswitch at the telco side and the
mediatrix and the softswitch talk sip but it's beyond my control."
If I was you I will do the follwoing:
1. find out the following, I remeber one of this direction may have some impact, like cannot detect on/off hook from FXS
If it's analog, Wireshark is out of option. Is FXO or FXS ?
Cisco FXS---- FXO mediatrix sip endpoint ?
or
Cisco FXO --- FXS mediatrix sip endpoint ?
2.
Get the SIP trace from mediatrix see when it sends back 200OK
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 14-11-2012 12:34:55 PM
Hi Yaw,
Since this doesn't look like a TCL script issue, is it possible we can involve TAC to help us review the router configurations? We tried to open a case with TAC but they said since there's a script involved, we have to come to developer support first but the issue seems to be a router issue.
Thanks.
Subject: RE: Leg setup command returns before call is connected
Replied by: Chris Manuh on 14-11-2012 02:14:11 PM
Hi Yaw,
The end point is Cisco FXO --- FXS mediatrix sip endpoin.
The sip log captured with the help of the telco on oct 25th is attached. The timing looks normal - 12 seconds to acceptance.
The log captured at a different time of the day from the mediatrix is also attached. The only thing i noticed from this log was that MakeCall request was received at 21:41:51 and about 21:41:54, we see these response. The interval is just about 4seconds which is when our TCL reports success. I don't know the meaning of these debug messages so I don't know if the two are related.
Oct 25 21:41:54 10.21.220.211 SipEngine [1BAE] Sending response to out of dialog OPTIONS.
Oct 25 21:41:54 10.21.221.62 CallManager [00A3] L9 C247076 ProgressingA.
Oct 25 21:41:54 10.21.221.62 CallManager [00A4] L9 C247076 InternalProgressingA - CallStatusA event sent | call status eSTATUS_PROGRESSING.
Oct 25 21:41:54 10.21.221.62 FxsInterface [00A5] L9 - Event CallStatus(5) on state "CONTROL WAITING RESPONSE"
Oct 25 21:41:54 10.21.221.62 FxsInterface [00A6] L9 - Change state from "CONTROL WAITING RESPONSE" to "CONTROL RING"
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 14-11-2012 04:09:51 PM
This is what I guessed too --> Cisco FXO --- FXS mediatrix sip endpoin
I wonder if we get "connected" because of FXS port, I wil check it out.
If posible just turn "deb vpm signal" on Cisco side see when we get.
Subject: RE: Leg setup command returns before call is connected
Replied by: Yaw-Ming Chen on 15-11-2012 12:13:26 PM
This is the fact of FXS feature,
Cisco FXO --- FXS mediatrix sip endpoin.
When we connect to FXS we get "connect" immediately.