Problem with GVP8 attached data using InteractionData block

[clemouk]

Just starting with GVP Composer Apps and I have a small sample app developed to test CTI functionality with UserData. We do not have CTI Connector deployed and therefore only have the SIPS ability to perform 'get' and 'put' operations. This is sufficient for our needs.

However, for some reason during debug the InteractionBlock fails and generates a' badfetch' error which doesn't seem to make any sense. The KVP is lowercase 'ivr_cust_selection' and isn't passed into the application; i.e. doesn't already exist which would generate an error without the CTIC.

If I run the application in production then the application finished without an error but when I look at the SIP logs there is no evidence of the KVP being attached. The userdata-map-filter for the VOIP DN is set to '*' so should include all keys. Also, the setting 'gvp.policy.cti-allowed' is set to false on the IVR profile.

The call trace shows a 32 second timeout period from calling the InteractionData block before generating a the 'error.badfetch' event

2012-02-07 10:41:03.473 - form_enter :UpdateUserData - 279
2012-02-07 10:41:03.473 - form_select :__FORMITEM_NAME_$43$_:BLOCK - 279
2012-02-07 10:41:03.582 - eval_cond :{AppState.g_CTICCall == 'false'}=true - 284
2012-02-07 10:41:03.582 - eval_script inline:53 done - 284
2012-02-07 10:41:35.629 - event error.badfetch.sip:1|send message timed out [Target: http://mcp:9090/App/src-gen/Main.vxml ] - 196

VXML:-

<if cond="AppState.g_CTICCall == 'false'" >
    <script>
    var ivr_cust_selection = AppState.ivr_cust_selection;
    </script>
    <gvp:send namelist="ivr_cust_selection" async="false"/>
<else/> .....

The debugger pauses on the line <gvp:send namelist="ivr_cust_selection" async="false"/> before generating the error.

Can anyone shed any light on this? Can provide sample app and call trace on request - seems upload folder is full 

Thanks
Lee

[René]

Hi Lee,

If you send me yr sample app and MCP log then I will have a look PM me url where I can download these.

R.

[clemouk]

Hi Rene - thank you so much for your offer of assistance.  I've sent you a PM with the details.

[René]

Hi Lee,

I checked the logs and found 2 issues

1/ DEBUG - MCP is sending SIP INFO messages to your SIP softphone but doesn't get any response so it reports timeout as you found in log already. Please double check that there is no firewall between your SIP softphone and MCP blocking the communication

[code]2012-02-07T14:13:12.964 Trc 33009 INFO 00000000-00000000 3534240656 02800FA1 Request sent: INFO sip:clemo@10.162.38.126:50601 SIP/2.0
Via: SIP/2.0/UDP 10.163.238.120:5070;branch=z9hG4bK24cbfad0313178
From: "dialog" <sip:dialog@10.163.238.104:5070;voicexml=http://10.162.38.126:9090/DataSupport%2Fsrc-gen%2FMain.vxml;gvp.debug=true>;tag=EB2BD93C-A41A-05A7-554F-4FFCA2CEA160
To: "Debugger" <sip:clemo@10.162.38.126:50601>;tag=vEIdE30uk2dd
Max-Forwards: 70
CSeq: 1 INFO
Call-ID: 7ff71aa90076644339dc1a413d600a9d@10.162.38.126
Content-Length: 25
Content-Type: application/x-www-form-urlencoded;charset=utf-8
X-Genesys-GVP-Session-ID: EB2BD93C-A41A-90BD-9E06-A8AA71BEF775
X-Genesys-Composer-Debug: cRqcrz6TR9
Supported: timer, uui

IVR_CUST_SELECTION=MOBILE

...
GVP re-sends INFO several times
...
2012-02-07 14:13:44.966 DBUG 00D900F3-10004DBD 3366399440 01C00000 CMCallLeg.C:1729 Call leg has received SIP INFO notification: RequestID=0, Status=-2 - Send data error.[/code]

2/ PRODUCTION - User Data are send out successfully by GVP (look for INFO SIP message) and you should these being attached to call in SIP Server log. However, sample application fails at the end as it tries to transfer call to other destination using REFER message. I assume that you invoked GVP from routing strategy = you can't transfer call from GVP application. You must end your GVP application and make transfer from routing strategy.

[code]2012-02-07T14:15:51.919 Trc 33009 INFO 00000000-00000000 3639036816 02800FA1 Request sent: REFER sip:0871643868@10.163.238.106:5060 SIP/2.0
Via: SIP/2.0/UDP 10.163.238.121:5070;branch=z9hG4bK202a0040313217
From: <sip:voip.service.msml@10.163.238.106:5060>;tag=2F741F10-F4DF-6CB7-D6BC-EE0991B30F0C
To: sip:0871643868@10.163.238.106;tag=0009AF10-FF9B-1F27-921D-75EEA30AAA77-561
Max-Forwards: 70
CSeq: 2 REFER
Call-ID: 0009AEE8-FF9B-1F27-921D-75EEA30AAA77-319@10.163.238.106
Contact: <sip:Genesys@10.163.238.105:5070>
Content-Length: 0
Route: <sip:200b6bb0@10.163.238.107:5060;lr;gvp.rm.datanodes=1;idtag=0000008D>
Referred-By: <sip:voip.service.msml@10.163.238.106:5060>
Refer-To: <sip:35600@10.163.238.106;user=phone;aai=0871643868>
X-Genesys-IVR_CUST_SELECTION: FIXED
X-Genesys-RETURN_RP: 35600
X-Genesys-GVP-Session-ID: EC2BD93C-E0E5-6301-261C-C44AACAC3217;gvp.rm.datanodes=1;gvp.rm.tenant-id=101_Default IVR Profile
gsw-ivr-profile-name: GVP_Test_App
Remote-Party-ID: <sip:0871643868@IPT57464.VODAFONE.IE>;party=calling;screen=yes;privacy=off
Date: Tue, 07 Feb 2012 14:15:13 GMT
Cisco-Guid: 4233497252-1355551201-2206387439-1221280768
User-Agent: Cisco-SIPGateway/IOS-15.2.2.T
Timestamp: 1328624113
Expires: 180
Content-Disposition: session;handling=required
Min-SE: 90
X-Genesys-GVP-Session-Data: callsession=EC2BD93C-E0E5-6301-261C-C44AACAC3217;1;0;;;;Resources;Default IVR Profile
Supported: timer, uui


2012-02-07T14:15:51.922 Trc 33009 INFO 00000000-00000000 3565607824 02800FA1 Response received: SIP/2.0 403 Forbidden
Via: SIP/2.0/UDP 10.163.238.121:5070;branch=z9hG4bK202a0040313217;received=10.163.238.105
From: <sip:voip.service.msml@10.163.238.106:5060>;tag=2F741F10-F4DF-6CB7-D6BC-EE0991B30F0C
To: sip:0871643868@10.163.238.106;tag=0009AF10-FF9B-1F27-921D-75EEA30AAA77-561;tag=EC2BD93C-E0E5-FA7D-20FA-BB2115B1A073
CSeq: 2 REFER
Call-ID: 0009AEE8-FF9B-1F27-921D-75EEA30AAA77-319@10.163.238.106
Content-Length: 0
Warning: 399 10.163.238.118 "Transfer Forbidden for IVR Profile [Default IVR Profile]"
[/code]


Hope it helps

R.

[clemouk]

Hi Rene,

We have implemented two networks, one data and one for voice but there are no firewalls between the media server and the agent endpoint. When I run a wireshark trace on the Composer desktop, I see the following SIP messaging

[code]
"No.","Time","Source","Destination","Protocol","Length","Info"
"802","18:06:49.529075","10.162.38.126","10.163.238.104","SIP/SDP","1042","Request: INVITE sip:dialog@10.163.238.104:5070;voicexml=http://10.162.38.126:9090/DataSupport%2Fsrc-gen%2FMain.vxml;gvp.debug=true, with session description"
"804","18:06:49.531968","10.163.238.104","10.162.38.126","SIP","459","Status: 100 Trying"
"815","18:06:49.718410","10.163.238.104","10.162.38.126","SIP","690","Status: 180 Ringing"
"841","18:06:49.919628","10.163.238.104","10.162.38.126","SIP/SDP","925","Status: 200 OK, with session description"
"845","18:06:49.924650","10.162.38.126","10.163.238.104","SIP","540","Request: ACK sip:Genesys@10.163.238.104:5070"
"10548","18:07:07.858978","10.163.238.104","10.162.38.126","SIP","716","Request: INFO sip:clemo@10.162.38.126:50601 (application/x-www-form-urlencoded)"
"10590","18:07:08.360610","10.163.238.104","10.162.38.126","SIP","716","Request: INFO sip:clemo@10.162.38.126:50601 (application/x-www-form-urlencoded)"
"10664","18:07:09.362509","10.163.238.104","10.162.38.126","SIP","716","Request: INFO sip:clemo@10.162.38.126:50601 (application/x-www-form-urlencoded)"
"10868","18:07:11.365341","10.163.238.104","10.162.38.126","SIP","716","Request: INFO sip:clemo@10.162.38.126:50601 (application/x-www-form-urlencoded)"
"11175","18:07:15.367880","10.163.238.104","10.162.38.126","SIP","716","Request: INFO sip:clemo@10.162.38.126:50601 (application/x-www-form-urlencoded)"
"11548","18:07:19.369449","10.163.238.104","10.162.38.126","SIP","716","Request: INFO sip:clemo@10.162.38.126:50601 (application/x-www-form-urlencoded)"
"11872","18:07:23.372047","10.163.238.104","10.162.38.126","SIP","716","Request: INFO sip:clemo@10.162.38.126:50601 (application/x-www-form-urlencoded)"
"12185","18:07:27.374431","10.163.238.104","10.162.38.126","SIP","716","Request: INFO sip:clemo@10.162.38.126:50601 (application/x-www-form-urlencoded)"
"12527","18:07:31.377200","10.163.238.104","10.162.38.126","SIP","716","Request: INFO sip:clemo@10.162.38.126:50601 (application/x-www-form-urlencoded)"
"12864","18:07:35.378612","10.163.238.104","10.162.38.126","SIP","716","Request: INFO sip:clemo@10.162.38.126:50601 (application/x-www-form-urlencoded)"
"13203","18:07:39.380350","10.163.238.104","10.162.38.126","SIP","716","Request: INFO sip:clemo@10.162.38.126:50601 (application/x-www-form-urlencoded)"
"14831","18:07:42.806587","10.163.238.104","10.162.38.126","SIP","702","Request: BYE sip:clemo@10.162.38.126:50601 (application/x-www-form-urlencoded)"
"14832","18:07:42.811654","10.162.38.126","10.163.238.104","SIP","479","Status: 200 OK"
"14848","18:07:42.826855","10.162.38.126","10.163.238.104","SIP","528","Request: BYE sip:Genesys@10.163.238.104:5070"
"14849","18:07:42.829506","10.163.238.104","10.162.38.126","SIP","481","Status: 200 OK"
[/code]

What is interesting is that when you inspect the initial INVITE packet, the contact header has changed to <From: "Debugger" <sip:clemo@10.162.38.126:50601>;tag=qPAUFu4tbLXo>. Note the port of "50601" - where does the extra 1 come from? In X-Lite I have specified the port range from 5060-5070, so nothing is listening on port "50601"?

Has Composer changed this and added the '1'?

[René]

Hi,

You should check SIP Server log to find out what port is used by X-Lite. However, I see in original INVITE message following From address -  "Debugger" <sip:clemo@10.162.38.126:50601>;tag=vEIdE30uk2dd so port was not changed.

R.

[clemouk]

Thanks Rene - yes that's the conclusion we have come to as well, strangely that port doesn't appear anywhere in either X-Lite configuration or Composer. It seems to have Genesys support stumped as well! 

[René]

Hi,

You won't find that port anywhere in X-Lite configuration as it is dynamically generated by OS (assumption). X-Lite is standard TCP client so client's (X-Lite's) port is dynamic (50601) and server's port is fixed (5060). You must ensure that firewall doesn't block the communication.

Have you tried using other SIP phone (e.g. Bria)?

R.

[clemouk]

René

The X-Lite configuration (on the Topology tab) has the 'Port used on local computer' set to a range of 5060-5070. So when the ACK comes back to 50601 there is nothing listening. I would expect Composer/X-Lite to set the contact header to the listening port and not the outbound client port.

We don't have any firewalls sitting on the SIP/RTP network so this should have nay impact; I've also tested this (just to be certain) and I am able to telnet to this port from the Media Server when I have a test client listening on that port.

For now I've included a debug flag in the application so that it simply doesn't execute the Interaction Data block in debug mode; this at least allows me to continue the application development.

Cheers,
Lee