Operation timing out

[metroscript]

Hello Plum Support,

We continue to have a problem intermittently and were hoping you could step in and help us, even if has to be paid help. Please see our post from Wednesday November 28, 2007 at 11:10 PM for some additional background information.

Our application is used by doctors who give their patient dictations. When this problem occurs, the dictation is lost, which is reallly bad because they then have to re-dictate.

Basically the VoiceXML in process_record_start.xml is trying to retrieve the next file from our IIS server, process_record_savevox.xml, but no response ever comes back to the Plum server, and we get the following error:

Operation timed out with 0 out of -1 bytes received

This error happens on the Plum side after 60 seconds because we have the fetch timeout set to 60 seconds.

We created our own server-side log to which we write entries via our server-side ASP code. At the very top of the process_record_savevox.xml file, we have a log write statement. That initial log entry is not showing up so it appears that the file is not being accessed at all, for some reason. So, we don't believe process_record_savevox.xml is being accessed and erroring out (and we get no entries in our IIS log or HTTP Error log).

Like I said this doesn't happen too often but it does happen maybe once a week. The latest was 1/14/2008 at around 10:33 AM ET. It was for a simple call (5 minute duration, no rewinding or anything like that).

When this happens when get no entries in our IIS log on the server and no entries in our HTTP Error log on the server. Here are the applicable log entries for yesterday's call:

***************************************************
PLUM ERROR LOG
***************************************************
error 5173391695 61 [14/Jan/2008:10:33:22 -0500] 8667211020 000004;061;1200322895 Error fetching document http://www.metroscript.com/voicexml/pro ... ext=hangup due to Operation timed out with 0 out of -1 bytes received

error 5173391695 61 [14/Jan/2008:10:33:22 -0500] 8667211020 000004;061;1200322895 DocumentParser::FetchBuffer - could not open URL: process_record_savevox.xml?next=hangup

error 5173391695 61 [14/Jan/2008:10:33:22 -0500] 8667211020 000004;061;1200322895 DocumentParser::FetchDocument - exiting with error result 2

error 5173391695 61 [14/Jan/2008:10:33:22 -0500] 8667211020 000004;061;1200322895 errno: 203 uri process_record_savevox.xml?next=hangup

error 5173391695 61 [14/Jan/2008:10:34:23 -0500] 8667211020 000004;061;1200322895 Error fetching document http://www.metroscript.com/voicexml/pro ... disconnect due to Operation timed out with 0 out of -1 bytes received

error 5173391695 61 [14/Jan/2008:10:34:23 -0500] 8667211020 000004;061;1200322895 DocumentParser::FetchBuffer - could not open URL: process_record_savevox.xml?next=disconnect

error 5173391695 61 [14/Jan/2008:10:34:23 -0500] 8667211020 000004;061;1200322895 DocumentParser::FetchDocument - exiting with error result 2

error 5173391695 61 [14/Jan/2008:10:34:23 -0500] 8667211020 000004;061;1200322895 errno: 203 uri process_record_savevox.xml?next=disconnect

error 5173391695 61 [14/Jan/2008:10:35:24 -0500] 8667211020 000004;061;1200322895 Error fetching document http://www.metroscript.com/voicexml/pro ... disconnect due to Operation timed out with 0 out of -1 bytes received

error 5173391695 61 [14/Jan/2008:10:35:24 -0500] 8667211020 000004;061;1200322895 DocumentParser::FetchBuffer - could not open URL: process_record_savevox.xml?next=disconnect
error 5173391695 61 [14/Jan/2008:10:35:24 -0500] 8667211020 000004;061;1200322895 DocumentParser::FetchDocument - exiting with error result 2

error 5173391695 61 [14/Jan/2008:10:35:24 -0500] 8667211020 000004;061;1200322895 errno: 203 uri process_record_savevox.xml?next=disconnect

error 5173391695 61 [14/Jan/2008:10:36:25 -0500] 8667211020 000004;061;1200322895 Error fetching document http://www.metroscript.com/voicexml/pro ... disconnect due to Operation timed out with 0 out of -1 bytes received

error 5173391695 61 [14/Jan/2008:10:36:25 -0500] 8667211020 000004;061;1200322895 DocumentParser::FetchBuffer - could not open URL: process_record_savevox.xml?next=disconnect
error 5173391695 61 [14/Jan/2008:10:36:25 -0500] 8667211020 000004;061;1200322895 DocumentParser::FetchDocument - exiting with error result 2

error 5173391695 61 [14/Jan/2008:10:36:25 -0500] 8667211020 000004;061;1200322895 errno: 203 uri process_record_savevox.xml?next=disconnect

error 5173391695 61 [14/Jan/2008:10:37:26 -0500] 8667211020 000004;061;1200322895 Error fetching document http://www.metroscript.com/voicexml/pro ... disconnect due to Operation timed out with 0 out of -1 bytes received

error 5173391695 61 [14/Jan/2008:10:37:26 -0500] 8667211020 000004;061;1200322895 DocumentParser::FetchBuffer - could not open URL: process_record_savevox.xml?next=disconnect
error 5173391695 61 [14/Jan/2008:10:37:26 -0500] 8667211020 000004;061;1200322895 DocumentParser::FetchDocument - exiting with error result 2

error 5173391695 61 [14/Jan/2008:10:37:26 -0500] 8667211020 000004;061;1200322895 errno: 203 uri process_record_savevox.xml?next=disconnect

error 5173391695 61 [14/Jan/2008:10:38:27 -0500] 8667211020 000004;061;1200322895 Error fetching document http://www.metroscript.com/voicexml/pro ... disconnect due to Operation timed out with 0 out of -1 bytes received

error 5173391695 61 [14/Jan/2008:10:38:27 -0500] 8667211020 000004;061;1200322895 DocumentParser::FetchBuffer - could not open URL: process_record_savevox.xml?next=disconnect
error 5173391695 61 [14/Jan/2008:10:38:27 -0500] 8667211020 000004;061;1200322895 DocumentParser::FetchDocument - exiting with error result 2

error 5173391695 61 [14/Jan/2008:10:38:27 -0500] 8667211020 000004;061;1200322895 errno: 203 uri process_record_savevox.xml?next=disconnect

error 5173391695 61 [14/Jan/2008:10:38:27 -0500] 8667211020 000004;061;1200322895 Max Error Count Exceeded


***************************************************
NORMAL PLUM LOG
***************************************************
local 5173391695 61 [[14/Jan/2008:10:27:23 -0500] 8667211020 000004;061;1200322895 label default.xml - End (Go to check_user_id.xml)

local 5173391695 61 [[14/Jan/2008:10:27:24 -0500] 8667211020 000004;061;1200322895 label check_user_id.xml - Start (User Id: 1252 User Name: 620000 Name: Doctor Thakur)

local 5173391695 61 [[14/Jan/2008:10:27:28 -0500] 8667211020 000004;061;1200322895 label check_user_id.xml - End (Go to check_password.xml)

local 5173391695 61 [[14/Jan/2008:10:27:28 -0500] 8667211020 000004;061;1200322895 label check_password.xml - Start (Confirmation Number: 218824)

local 5173391695 61 [[14/Jan/2008:10:27:28 -0500] 8667211020 000004;061;1200322895 label check_password.xml - End (Go to main_menu_setup.xml)

local 5173391695 61 [[14/Jan/2008:10:27:35 -0500] 8667211020 000004;061;1200322895 label main_menu_setup.xml - Start and End (Go to main_menu.xml)

local 5173391695 61 [[14/Jan/2008:10:27:39 -0500] 8667211020 000004;061;1200322895 label main_menu.xml - Start and End (User Choice 1, Go to process_record_new.xml)

local 5173391695 61 [[14/Jan/2008:10:27:40 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - Start

local 5173391695 61 [[14/Jan/2008:10:32:18 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - MID (File size in bytes: 2200576 ,Go to process_record_savevox.xml?next=hangup )

local 5173391695 61 [[14/Jan/2008:10:32:18 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - End (User Choice *, Go to process_record_savevox.xml?next=hangup )

local 5173391695 61 [[14/Jan/2008:10:33:22 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - MID (File size in bytes: 2200576 , Go to process_record_savevox.xml?next=disconnect )

local 5173391695 61 [[14/Jan/2008:10:33:22 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - End (error.badfetch during recording, Go to process_record_savevox.xml?next=disconnect)

local 5173391695 61 [[14/Jan/2008:10:33:22 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - MID (File size in bytes: 2200576 , Go to process_record_savevox.xml?next=disconnect )

local 5173391695 61 [[14/Jan/2008:10:33:22 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - End (disconnect during recording, Go to process_record_savevox.xml?next=disconnect )

local 5173391695 61 [[14/Jan/2008:10:34:23 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - MID (File size in bytes: 2200576 , Go to process_record_savevox.xml?next=disconnect )

local 5173391695 61 [[14/Jan/2008:10:34:23 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - End (error.badfetch during recording, Go to process_record_savevox.xml?next=disconnect)

local 5173391695 61 [[14/Jan/2008:10:35:24 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - MID (File size in bytes: 2200576 , Go to process_record_savevox.xml?next=disconnect )

local 5173391695 61 [[14/Jan/2008:10:35:24 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - End (error.badfetch during recording, Go to process_record_savevox.xml?next=disconnect)

local 5173391695 61 [[14/Jan/2008:10:36:25 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - MID (File size in bytes: 2200576 , Go to process_record_savevox.xml?next=disconnect )

local 5173391695 61 [[14/Jan/2008:10:36:25 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - End (error.badfetch during recording, Go to process_record_savevox.xml?next=disconnect)

local 5173391695 61 [[14/Jan/2008:10:37:26 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - MID (File size in bytes: 2200576 , Go to process_record_savevox.xml?next=disconnect )

local 5173391695 61 [[14/Jan/2008:10:37:26 -0500] 8667211020 000004;061;1200322895 label process_record_start.xml - End (error.badfetch during recording, Go to process_record_savevox.xml?next=disconnect)

inbound 5173391695 61 [[14/Jan/2008:10:38:28 -0500] 8667211020 000004;061;1200322895 1200324430 1200325108 0:11:18

***************************************************
OUR HOME-GROWN ASP LOG
***************************************************
1/14/2008 10:25:49 AM 000004;061;1200322895 main_menu_setup.xml - Start and End (CallID:96151 Name:Doctor Thakur UserID:1252 UserName:620000)

1/14/2008 10:25:53 AM 000004;061;1200322895
process_record_new.xml - Start

1/14/2008 10:25:53 AM 000004;061;1200322895 process_record_new.xml - End

1/14/2008 10:25:53 AM 000004;061;1200322895
process_record_start.xml - Start and End

We can not figure out why the call to process_record_savevox.xml is failing every so often in a scenario where it has succeeded a hundred times before. Do you have any support option where a technician can dedicate some time to this and help us troubleshoot this? Like I said, we would understand if there would be an additional fee involved for the support. But we've been battling this for a long time and can't put it to bed.

Please advise.

Thanks,

Charlie Pasquine

[support]

Hi,

Yes, we have an IVR developer support option where a Plum developer can dedicate some time to solve this IVR issue.

You should talk to your account manager about setting up a direct developer support account.

Regards,
Plum Support

[metroscript]

OK, I will talk to Scott if we want to pursue that option. In the mean time, we are trying a couple of more things before we throw in the towel. As such, can you please give me your feedback on these items?

It is obvious that your server is not able to fetch http://www.metroscript.com/voicexml/pro ... avevox.xml from our server when this problem arises. So, in our minds, this has to be one of two things causing this -- either your DNS server is unable to resolve the domain or our IIS server is unable to process the request at ll. Would you agree so far? Have you seen any other issues in the past that could prevent a clean fetch? (Remember, we're pretty certain that the process_record_savevox.xml is not being reached because one of the first things we do in that xml file on our server is write a log entry, "we are here," to our ASP log, and we are not seeing that entry).

To take the DNS out of the equation, we've gone into the Plum interface for our app, and we've changed our "starting page" paths to use the IP address of our web site instead of the domain name. Does this sound like a reasonable thing to do and can you foresee any issues in us doing this?

If the problem still occurs then we almost have to point the finger at IIS. Given your experience, can you think of any reasons why IIS would ignore a series of five consecutive requests from your server, spread out over a 5 minute period? Doesn't make sense, does it? can you offer up any suggestions in this realm? Maybe you have an IIS guru on hand there with whom you could touch base?

Thanks for the help.

Charlie

[support]

Hi,

We have had an IVR issue like this before, mentioned in this post: http://support.plumvoice.com/viewtopic.php?t=571

Possibly, it might be a configuration issue on your web server in how it handles persistent HTTP/1.1 connections. You should consult your web server configuration guide and look into disabling persistent HTTP connections.

As for your suggestion on removing DNS from the equation, there should be no problem with changing your starting page to use the IP address of your web site instead.

As for your IIS questions, we unfortunately do not have anyone in-house with IIS expertise.

Regards,
Plum Support